LHC@home

Hello,

After I upgraded to the latest BONIC and VM releases a few days ago, all my LHC tasks fail more or less immediately. Any suggestions for this problem? Below is a sample error log:

Stderr output
<core_client_version>7.22.2</core_client_version>
<![CDATA[
<message>
Incorrect function.
(0x1) - exit code 1 (0x1)</message>
<stderr_txt>
2023-07-01 17:36:46 (4980): Detected: vboxwrapper 26206
2023-07-01 17:36:46 (4980): Detected: BOINC client v7.22.2
2023-07-01 17:36:49 (4980): Detected: VirtualBox VboxManage Interface (Version: 7.0.6)
2023-07-01 17:36:50 (4980): Detected: Heartbeat check (file: 'heartbeat' every 1200.000000 seconds)
2023-07-01 17:36:50 (4980): Successfully copied 'init_data.xml' to the shared directory.
2023-07-01 17:36:53 (4980): Create VM. (boinc_677395e36e5cb228, slot#23)
2023-07-01 17:36:55 (4980): Setting Memory Size for VM. (2048MB)
2023-07-01 17:36:57 (4980): Setting CPU Count for VM. (1)
2023-07-01 17:36:58 (4980): Setting Chipset Options for VM.
2023-07-01 17:37:00 (4980): Setting Graphics Controller Options for VM.
2023-07-01 17:37:01 (4980): Setting Boot Options for VM.
2023-07-01 17:37:02 (4980): Setting Network Configuration for NAT.
2023-07-01 17:37:03 (4980): Enabling VM Network Access.
2023-07-01 17:37:05 (4980): Disabling USB Support for VM.
2023-07-01 17:37:06 (4980): Disabling COM Port Support for VM.
2023-07-01 17:37:08 (4980): Disabling LPT Port Support for VM.
2023-07-01 17:37:09 (4980): Disabling Audio Support for VM.
2023-07-01 17:37:11 (4980): Disabling Clipboard Support for VM.
2023-07-01 17:37:12 (4980): Disabling Drag and Drop Support for VM.
2023-07-01 17:37:13 (4980): Adding storage controller(s) to VM.
2023-07-01 17:37:14 (4980): Adding virtual disk drive to VM. (CMS_2022_09_07_prod.vdi)
2023-07-01 17:37:23 (4980): Adding VirtualBox Guest Additions to VM.
2023-07-01 17:37:24 (4980): Adding network bandwidth throttle group to VM. (Defaulting to 1024GB)
2023-07-01 17:37:26 (4980): forwarding host port 63776 to guest port 80
2023-07-01 17:37:27 (4980): Enabling remote desktop for VM.
2023-07-01 17:37:28 (4980): Required extension pack not installed, remote desktop not enabled.
2023-07-01 17:37:28 (4980): Enabling shared directory for VM.
2023-07-01 17:37:32 (4980): Starting VM using VBoxManage interface. (boinc_677395e36e5cb228, slot#23)
2023-07-01 17:37:36 (4980): Error in start VM for VM: 1
Command:
VBoxManage -q startvm "boinc_677395e36e5cb228" --type headless
Output:
VBoxManage.exe: error: The virtual machine 'boinc_677395e36e5cb228' has terminated unexpectedly during startup with exit code 1 (0x1). More details may be available in 'D:\ProgramData\slots\23\boinc_677395e36e5cb228\Logs\VBoxHardening.log'
VBoxManage.exe: error: Details: code E_FAIL (0x80004005), component MachineWrap, interface IMachine
Waiting for VM "boinc_677395e36e5cb228" to power on...

2023-07-01 17:37:36 (4980): VM failed to start.
2023-07-01 17:37:36 (4980): Could not start
2023-07-01 17:37:36 (4980): ERROR: VM failed to start
2023-07-01 17:37:36 (4980): Powering off VM.
2023-07-01 17:37:36 (4980): Deregistering VM. (boinc_677395e36e5cb228, slot#23)
2023-07-01 17:37:38 (4980): Removing network bandwidth throttle group from VM.
2023-07-01 17:37:39 (4980): Removing VM from VirtualBox.

Hypervisor System Log:

00:00:53.526154 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526159 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526164 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526168 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526173 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526178 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526184 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526189 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526194 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526199 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526204 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526209 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526214 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526219 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526224 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526228 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526233 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526238 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526243 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526248 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526252 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526257 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526262 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526267 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526271 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526277 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526282 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526287 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526292 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526297 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526301 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526306 ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={300763af-5d6b-46e6-aa96-273eac15538a} aComponent={MachineWrap} aText={The object functionality is limited}, preserve=false aResultDetail=0
00:00:53.526383 Saving settings file "C:\Users\Brian\.VirtualBox\VirtualBox.xml" with version "1.12-windows"
00:00:53.529380 Finished saving settings file "C:\Users\Brian\.VirtualBox\VirtualBox.xml"
00:00:53.529460 Saving settings file "C:\Users\Brian\.VirtualBox\VirtualBox.xml" with version "1.12-windows"
00:00:53.531779 Finished saving settings file "C:\Users\Brian\.VirtualBox\VirtualBox.xml"
00:00:53.532387 DeleteVM Saving settings file "C:\Users\Brian\.VirtualBox\VirtualBox.xml" with version "1.12-windows"
00:00:53.534667 DeleteVM Finished saving settings file "C:\Users\Brian\.VirtualBox\VirtualBox.xml"
00:00:58.540178 main VirtualBox: object deletion starts
00:00:58.541589 main HostDnsMonitor: shutting down ...
00:00:58.541617 main HostDnsMonitor: shut down
00:00:58.542117 Watcher ERROR [COM]: aRC=E_ACCESSDENIED (0x80070005) aIID={7682d5eb-f00e-44f1-8ca2-99d08b1cd607} aComponent={VirtualBoxWrap} aText={The object is not ready}, preserve=false aResultDetail=0
00:00:58.542318 main VirtualBox: object deleted

VM Execution Log:


VM Startup Log:


VM Trace Log:

):
Command: VBoxManage -q showvminfo "boinc_677395e36e5cb228" --machinereadable
Exit Code: -2135228415
Output:
VBoxManage.exe: error: Could not find a registered machine named 'boinc_677395e36e5cb228'
VBoxManage.exe: error: Details: code VBOX_E_OBJECT_NOT_FOUND (0x80bb0001), component VirtualBoxWrap, interface IVirtualBox, callee IUnknown
VBoxManage.exe: error: Context: "FindMachine(Bstr(VMNameOrUuid).raw(), machine.asOutParam())" at line 3139 of file VBoxManageInfo.cpp

2023-07-01 17:36:53 (4980):
Command: VBoxManage -q showhdinfo "D:\ProgramData\slots\23/vm_image.vdi"
Exit Code: -2135228412
Output:
VBoxManage.exe: error: Could not find file for the medium 'D:\ProgramData\slots\23\vm_image.vdi' (VERR_FILE_NOT_FOUND)
VBoxManage.exe: error: Details: code VBOX_E_FILE_ERROR (0x80bb0004), component MediumWrap, interface IMedium, callee IUnknown
VBoxManage.exe: error: Context: "OpenMedium(Bstr(pszFilenameOrUuid).raw(), enmDevType, enmAccessMode, fForceNewUuidOnOpen, pMedium.asOutParam())" at line 205 of file VBoxManageDisk.cpp

2023-07-01 17:36:54 (4980):
Command: VBoxManage -q createvm --name "boinc_677395e36e5cb228" --basefolder "D:\ProgramData\slots\23" --ostype "Linux26_64" --register
Exit Code: 0
Output:
Virtual machine 'boinc_677395e36e5cb228' is created and registered.
UUID: ff16f52a-8aef-4e9f-8e71-e2d1ff152855
Settings file: 'D:\ProgramData\slots\23\boinc_677395e36e5cb228\boinc_677395e36e5cb228.vbox'

2023-07-01 17:36:55 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --description "CMS_2958921_1688245552.777433_0"
Exit Code: 0
Output:

2023-07-01 17:36:57 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --memory 2048
Exit Code: 0
Output:

2023-07-01 17:36:58 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --cpus 1
Exit Code: 0
Output:

2023-07-01 17:37:00 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --acpi on --ioapic on --rtcuseutc off
Exit Code: 0
Output:

2023-07-01 17:37:01 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --vram 16 --graphicscontroller VBoxVGA
Exit Code: 0
Output:

2023-07-01 17:37:02 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --boot1 disk --boot2 dvd --boot3 none --boot4 none
Exit Code: 0
Output:

2023-07-01 17:37:03 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --nic1 nat --natdnsproxy1 on --cableconnected1 off
Exit Code: 0
Output:

2023-07-01 17:37:05 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --cableconnected1 on
Exit Code: 0
Output:

2023-07-01 17:37:06 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --usb off
Exit Code: 0
Output:

2023-07-01 17:37:08 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --uart1 off --uart2 off
Exit Code: 0
Output:

2023-07-01 17:37:09 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --lpt1 off --lpt2 off
Exit Code: 0
Output:

2023-07-01 17:37:11 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --audio none
Exit Code: 0
Output:
Warning: --audio is deprecated and will be removed soon. Use --audio-driver instead!

2023-07-01 17:37:12 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --clipboard disabled
Exit Code: 0
Output:

2023-07-01 17:37:13 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --draganddrop disabled
Exit Code: 0
Output:

2023-07-01 17:37:14 (4980):
Command: VBoxManage -q storagectl "boinc_677395e36e5cb228" --name "Hard Disk Controller" --add "sata" --controller "IntelAHCI" --hostiocache off --portcount 3
Exit Code: 0
Output:

2023-07-01 17:37:16 (4980):
Command: VBoxManage -q showhdinfo "D:\ProgramData/projects/lhcathome.cern.ch_lhcathome/CMS_2022_09_07_prod.vdi"
Exit Code: 0
Output:
UUID: dae25e8f-de18-4971-b11c-eca764ede402
Parent UUID: base
State: created
Type: multiattach
Location: D:\ProgramData\projects\lhcathome.cern.ch_lhcathome\CMS_2022_09_07_prod.vdi
Storage format: VDI
Format variant: dynamic default
Capacity: 20480 MBytes
Size on disk: 3853 MBytes
Encryption: disabled
Property: AllocationBlockSize=1048576

2023-07-01 17:37:17 (4980):
Command: VBoxManage -q storageattach "boinc_677395e36e5cb228" --storagectl "Hard Disk Controller" --port 0 --device 0 --type hdd --mtype multiattach --medium "D:\ProgramData/projects/lhcathome.cern.ch_lhcathome/CMS_2022_09_07_prod.vdi"
Exit Code: -2135228409
Output:
VBoxManage.exe: error: Cannot change type for medium 'D:\ProgramData\projects\lhcathome.cern.ch_lhcathome\CMS_2022_09_07_prod.vdi': the media type 'MultiAttach' can only be used on media registered with a machine that was created with VirtualBox 4.0 or later
VBoxManage.exe: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component MediumWrap, interface IMedium, callee IUnknown
VBoxManage.exe: error: Context: "COMSETTER(Type)(enmMediumType)" at line 717 of file VBoxManageStorageController.cpp
VBoxManage.exe: error: Failed to set the medium type

2023-07-01 17:37:19 (4980):
Command: VBoxManage -q storageattach "boinc_677395e36e5cb228" --storagectl "Hard Disk Controller" --port 0 --device 0 --type hdd --mtype multiattach --medium "D:\ProgramData/projects/lhcathome.cern.ch_lhcathome/CMS_2022_09_07_prod.vdi"
Exit Code: -2135228409
Output:
VBoxManage.exe: error: Cannot change the type of medium 'D:\ProgramData\projects\lhcathome.cern.ch_lhcathome\CMS_2022_09_07_prod.vdi' because it is attached to 4 virtual machines
VBoxManage.exe: error: Details: code VBOX_E_INVALID_OBJECT_STATE (0x80bb0007), component MediumWrap, interface IMedium, callee IUnknown
VBoxManage.exe: error: Context: "COMSETTER(Type)(enmMediumType)" at line 717 of file VBoxManageStorageController.cpp
VBoxManage.exe: error: Failed to set the medium type

2023-07-01 17:37:23 (4980):
Command: VBoxManage -q storageattach "boinc_677395e36e5cb228" --storagectl "Hard Disk Controller" --port 0 --device 0 --type hdd --mtype multiattach --medium "D:\ProgramData/projects/lhcathome.cern.ch_lhcathome/CMS_2022_09_07_prod.vdi"
Exit Code: 0
Output:

2023-07-01 17:37:24 (4980):
Command: VBoxManage -q storageattach "boinc_677395e36e5cb228" --storagectl "Hard Disk Controller" --port 1 --device 0 --type dvddrive --medium "C:\Program Files\Oracle\VirtualBox/VBoxGuestAdditions.iso"
Exit Code: 0
Output:

2023-07-01 17:37:26 (4980):
Command: VBoxManage -q bandwidthctl "boinc_677395e36e5cb228" add "boinc_677395e36e5cb228_net" --type network --limit 1024G
Exit Code: 0
Output:

2023-07-01 17:37:27 (4980):
Command: VBoxManage -q modifyvm "boinc_677395e36e5cb228" --natpf1 ",tcp,127.0.0.1,63776,,80"
Exit Code: 0
Output:

2023-07-01 17:37:28 (4980):
Command: VBoxManage -q list extpacks
Exit Code: 0
Output:
Extension Packs: 0

2023-07-01 17:37:30 (4980):
Command: VBoxManage -q sharedfolder add "boinc_677395e36e5cb228" --name "shared" --hostpath "D:\ProgramData\slots\23/shared"
Exit Code: 0
Output:

2023-07-01 17:37:36 (4980):
Command: VBoxManage -q startvm "boinc_677395e36e5cb228" --type headless
Exit Code: 1
Output:
VBoxManage.exe: error: The virtual machine 'boinc_677395e36e5cb228' has terminated unexpectedly during startup with exit code 1 (0x1). More details may be available in 'D:\ProgramData\slots\23\boinc_677395e36e5cb228\Logs\VBoxHardening.log'
VBoxManage.exe: error: Details: code E_FAIL (0x80004005), component MachineWrap, interface IMachine
Waiting for VM "boinc_677395e36e5cb228" to power on...

2023-07-01 17:37:38 (4980):
Command: VBoxManage -q snapshot "boinc_677395e36e5cb228" list
Exit Code: -108
Output:
This machine does not have any snapshots

2023-07-01 17:37:39 (4980):
Command: VBoxManage -q bandwidthctl "boinc_677395e36e5cb228" remove "boinc_677395e36e5cb228_net"
Exit Code: 0
Output:

2023-07-01 17:37:40 (4980):
Command: VBoxManage -q unregistervm "boinc_677395e36e5cb228" --delete
Exit Code: 0
Output:
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%

17:37:46 (4980): called boinc_finish(1)

</stderr_txt>
]]>

I'd start by installing the guest additions that go along with that VBox version and see what happens from there.

Looks like you had some VMs in a running/suspended state when you did the VirtualBox upgrade.
This messed the VMs.

The following steps assume that you use VirtualBox only for BOINC.
If you run own VMs beside BOINC you must stop/backup them and restore/reattach them later.

What you need to do now is to clean your BOINC and VirtualBox environment including
- cancel all running vbox tasks and report them back
- do a project reset (at least for LHC@home)
- remove VirtualBox -> reboot
- remove all "VirtualBox.xml" files. On Windows they are usually below <drive_letter>:\Users\<user>\.VirtualBox
- remove VirtualBox entries from the Windows registry (sometimes they survive an uninstall) -> reboot
- reinstall the most recent VirtualBox -> reboot
- restart BOINC and get fresh work

Thank you! Your instructions solved the problem.