LHC@home

My Win10 host is running BOINC 7.16.20 with vBox 6.1.16 plus the 6.1.16 Extension pack. I've been encountering this issue where my CMS tasks are failing because vBox is unable to find the VM to run the task. I've uninstalled and reinstalled BOINC and vBox several times with the issue persisting. I'm unsure how to continue troubleshooting this.

Most recent failed task
https://lhcathome.cern.ch/lhcathome/result.php?resultid=332187349

Tasks page for my host
https://lhcathome.cern.ch/lhcathome/results.php?hostid=10687301&offset=0&show_names=0&state=6&appid=11

I can see in the BOINC logs that the VM is started in a project slot

2021-11-10 14:25:35 (15216): forwarding host port 52026 to guest port 80
2021-11-10 14:25:35 (15216): Enabling remote desktop for VM.
2021-11-10 14:25:36 (15216): Enabling shared directory for VM.
2021-11-10 14:25:36 (15216): Starting VM using VBoxManage interface. (boinc_62fd0aaede4ddcf6, slot#16)
2021-11-10 14:25:41 (15216): Successfully started VM. (PID = '2380')
2021-11-10 14:25:41 (15216): Reporting VM Process ID to BOINC.
2021-11-10 14:25:41 (15216): Guest Log: BIOS: VirtualBox 6.1.16
2021-11-10 14:25:41 (15216): Guest Log: CPUID EDX: 0x178bfbff
2021-11-10 14:25:41 (15216): Guest Log: BIOS: ata0-0: PCHS=16383/16/63 LCHS=1024/255/63
2021-11-10 14:25:41 (15216): VM state change detected. (old = 'poweredoff', new = 'running')

But then a short time later, in the vBox hypervisor logs show that the registered VM cannot be found.

17:35:01.292412          ERROR [COM]: aRC=VBOX_E_OBJECT_NOT_FOUND (0x80bb0001) aIID={d0a0163f-e254-4e5b-a1f2-011cf991c38d} aComponent={VirtualBoxWrap} aText={Could not find a registered machine named 'boinc_62fd0aaede4ddcf6'}, preserve=false aResultDetail=0

The VM trace logs show that it takes about 20 minutes for it to error out and initiate a shutdown of the VM even though it logs it starting.

2021-11-10 14:25:36 (15216): 
Command: VBoxManage -q sharedfolder add "boinc_62fd0aaede4ddcf6" --name "shared" --hostpath "C:\ProgramData\BOINC\slots\16/shared"
Exit Code: 0
Output:

2021-11-10 14:25:40 (15216): 
Command: VBoxManage -q startvm "boinc_62fd0aaede4ddcf6" --type headless
Exit Code: 0
Output:
Waiting for VM "boinc_62fd0aaede4ddcf6" to power on...
VM "boinc_62fd0aaede4ddcf6" has been successfully started.

2021-11-10 14:25:42 (15216): 
Command: VBoxManage -q controlvm "boinc_62fd0aaede4ddcf6" cpuexecutioncap 100 
Exit Code: 0
Output:

2021-11-10 14:45:43 (15216): 
Command: VBoxManage -q controlvm "boinc_62fd0aaede4ddcf6" poweroff
Exit Code: 0
Output:
0%...10%...20%...30%...40%...50%...60%...70%...80%...90%...100%

2021-11-10 14:45:43 (15216): 
Command: VBoxManage -q snapshot "boinc_62fd0aaede4ddcf6" list 
Exit Code: -108
Output:
This machine does not have any snapshots

2021-11-10 14:45:44 (15216): 
Command: VBoxManage -q bandwidthctl "boinc_62fd0aaede4ddcf6" remove "boinc_62fd0aaede4ddcf6_net" 
Exit Code: 0
Output:

What can be looked at next to nail this error down?

R/S

Scott

The tasks fail very early.
This can be seen looking at the CPU time (only 35 seconds).

After that the VM remains idle until the heartbeat watchdog shuts down the VM (hence the long total runtime):

2021-11-10 14:45:43 (15216): VM Heartbeat file specified, but missing.
2021-11-10 14:45:43 (15216): VM Heartbeat file specified, but missing file system status. (errno = '2')

Errors reported after that are caused by some kind of a race condition:
There are subroutines that try to check/report the VM's status while others are working on the shutdown.


To solve the issue it's necessary to find out why the tasks fail early.
Possible reasons:
- the vdi got damaged -> reset the project to get a fresh download
- wrong/incomplete access rights in \slots\ -> the BOINC user/group requires write access to create/update the vdi and the watchdog file
- overloaded disk I/O; How many tasks are writing to the disk concurrently? Is there enough RAM left for the disk cache?

I just reset the project and will know what that does tomorrow afternoon.

On the permissions front, my user account runs the BOINC process and and Full Control rights to the C:\ProgramData\BOINC and C:\ProgramData\BOINC\slots directories. I can see my user account owns the processes for BOINC Mgr and the running tasks via Process Explorer.

My host has a Samsung 860 EVO 1TB SSD and resource monitor shows disk I/O from 1-4% with BOINC running 16 threads of Rosetta@home tasks. In Use memory is at ~17GB out of 32GB in the system. When I was attempting to run more than two CMS tasks a while back, I would get notices in BOINC that a CMS task was paused, waiting for memory. That said, I've had 14 Rosetta and 2 CMS tasks running concurrently on this host. The past few days LHC@home has only assigned a single CMS task to this host due to the number of failures.

R/S
Scott

This CPU (AMD Ryzen 7 3700X) has 8 floating point units which are under extreme load if you run 14 Rosetta tasks and 2 CMS tasks concurrently.
Linux provides a monitoring value called "load average" which gives an impression of how many commands are waiting for execution in the CPU queue.
Unfortunately Windows doesn't provide a comparable monitoring value.

In reality the correlation is much more complex but it doesn't help to get lost deeper in any details.
What you see is the result of running too many heavy processes concurrently.
At a certain point they start to switch into a panic mode that makes the situation even worse.
To stay below that point you may try to run an project mix that puts less load on the floating point units.

Now is 19043 active. Your PC show:
Microsoft Windows 10 Professional x64 Edition, (10.00.19042.00)
As computezrmle said, reduce your work in Boinc to see when RAM is running without swapping.

Thanks. I've set Rosetta to not fetch new tasks so only LHC CMS tasks will run. I'll see if that does it.
If it does, is this an issue of needing more system memory so everything can run in memory without drive swapping? Or is this a limitation on floating point calculations of the processor?

R/S
Scott

A while ago you wrote:

... In Use memory is at ~17GB out of 32GB ...

Now you wrote:

... everything can run in memory without drive swapping?

Sure you see (heavy) swapping activity?
Looks like half of your RAM is unused or used by the disk cache.

That's just it, no I do not see it. I'm going down the path of troubleshooting the vbox.log and vboxhardening.log of the individual VMs when they are running. I've also uninstalled my AntiVirus, rebooted, and ensured its cleared out. The last CMS task my host got yesturday was during a time when Rosetta@home was not sending tasks and my host only had a couple of them running when the CMS task started.

https://lhcathome.cern.ch/lhcathome/result.php?resultid=332568799

The CMS task stderr log shows that it there was 26374 MB of memory available when it started.

Memory size: 32673 MByte
Memory available: 26374 MByte

This task still failed in the same way as the past several days despite a much lower CPU and memory load.

Note: I have a companion thread to this one on vbox.log and vboxhardening.log capture.
https://lhcathome.cern.ch/lhcathome/forum_thread.php?id=5754

That is from your CMS-task with no success:
2021-11-11 12:57:41 (15744): Setting checkpoint interval to 600 seconds. (Higher value of (Preference: 600 seconds) or (Vbox_job.xml: 600 seconds))
That is from a successful CMS-Task:
2021-11-06 07:18:56 (12680): Detected: Heartbeat check (file: 'heartbeat' every 1200.000000 seconds)

That is from your CMS-task with no success:
2021-11-11 12:57:41 (15744): Setting checkpoint interval to 600 seconds. (Higher value of (Preference: 600 seconds) or (Vbox_job.xml: 600 seconds))
That is from a successful CMS-Task:
2021-11-06 07:18:56 (12680): Detected: Heartbeat check (file: 'heartbeat' every 1200.000000 seconds)

I'm not understanding how that can help. The heartbeat time frame is a variable of the project/task. It's not a user configurable setting that would need to be "corrected" to ensure tasks complete.

(Vbox_job.xml: 600 seconds)
Don't find it in my CMS-Task.
In a Theory-task is this line shown:
2021-11-12 14:11:49 (5584): Setting checkpoint interval to 1200 seconds. (Higher value of (Preference: 1200 seconds) or (Vbox_job.xml: 600 seconds))

So removing Anti-virus did not solve the issue. This task just failed at 1349 EST.

https://lhcathome.cern.ch/lhcathome/result.php?resultid=332726303

It still looks like a credential issue.

Did you see this?

    Hypervisor System Log:

00:00:00.262874          ExtPack: Created cloud provider 'OCI' (hrc=ERROR_SUCCESS)

Did you check this?
https://www.virtualbox.org/manual/ch01.html#cloud-integration
https://forums.virtualbox.org/viewtopic.php?f=6&t=93953

I made a guestimate and was waiting on my host when it received a CMS task. I've captured the VBox, VBoxHardening, VBoxUI, and vbox_trace logs from the ./slots/ folder the task was running in. I'm posting to the VirtualBox forums for help in troubleshooting the logs.

https://forums.virtualbox.org/viewtopic.php?f=3&t=104465

If anyone knows how to review and troubleshoot VBox logs, I've uploaded them to a workdrive space
https://workdrive.zoho.com/folder/pgoec33ffeb6d9e36461c9a953c076976b93c

R/S
Scott

Maybe there is a lot of junk media left over from crashed VM's, since it looks like the hard disk was lost.

In regards to the comments on the VirtualBox thread, I think it by design that there is 8MB of VRAM there is no GUI in the VM image so no need for 128MB of graphics memory. its also by design that there is one CPU core and 2 GB of ram to no swamp the host computers with tons of ram usage.

Sometimes i get the hung one with exactly the same error:

https://lhcathome.cern.ch/lhcathome/result.php?resultid=332767550

but I ignore them since they are only 0.3% of total.

Sometime I got stuck in many errors I just abort everything, ensure everything is empty in BOINC and VirtualBox, limit it just to one WU at a time to see if it cleaned out then ramp up from there.

Maybe there is a lot of junk media left over from crashed VM's, since it looks like the hard disk was lost.

I experienced issues that left junk in the .\slots\ folder and it was one of the first troubleshooting steps I did when I started digging into this on my Win10 client. The VM crash persists through multiple VirtualBox versions, 6.1.12, 6.1.16, 6.1.28 and ensuring the BOINC data directory .\slots\ folders and the VBox manager are clean.

So far, I've not gotten far on the Virtual Box forums. There are some suggestions on the underlying configuration of the LHC@Home VM, but I'm not in anyway qualified to raise these to the project. As far as I can search on the LHC@Home forums, I can't find anything like what I'm experiencing. If it goes on much longer with no appreciable suggestions on troubleshooting on the contents of the log files, I may have to just remove the project from my Win10 host. I don't want to do that. But I won't have a choice if I can't troubleshoot the issue and just keep sending failing work-units back.

https://lhcathome.cern.ch/lhcathome/results.php?hostid=10687301&offset=0&show_names=0&state=6&appid=11

What's about running Atlas or Theory instead of CMS, to see what happens.
They need also Virtualbox.

There's a relevant change in the logfile entries starting with this task:
https://lhcathome.cern.ch/lhcathome/result.php?resultid=333033783


Before the errors started with a long delay after the VM jumped into the bootstrap script:

2021-11-15 10:14:24 (13320): Guest Log: 00:00:00.001316 main     5.2.6 r120293 started. Verbose level = 0

### VM hangs here

2021-11-15 10:28:48 (13320): Guest Log: [INFO] Mounting the shared directory
2021-11-15 10:32:54 (13320): VM Heartbeat file specified, but missing.
2021-11-15 10:32:54 (13320): VM Heartbeat file specified, but missing file system status. (errno = '2')

This finally results in a heartbeat shutdown.



The new logfiles show that the VM successfully completes the bootstrap script and starts "glidein" which is the main wrapper of the scientific payload.

2021-11-16 10:12:32 (3888): Guest Log: [INFO] CMS application starting. Check log files.
2021-11-16 10:47:43 (3888): Guest Log: [ERROR] glidein exited with return value 1.

The major difference is that newer tasks use a local Squid which allows to download additional scripts required within bootstrap.
This also affects scripts that are essential to make the logfile more verbose or test important network connections.
Older tasks do not use the Squid. Hence, I suspect direct HTTP request from that computer to CERN might be blocked by a local firewall.

I also suspect this to be the reason why glidein fails.
The VM requires a couple of TCP ports to be open.
Beside the ports that are tested within bootstrap CMS requires 1094 and 8000.

I went and looked that over and see what you've found. I believe that is when I updated VBox to 6.1.28. I did see the Glidin error a few days ago and began looking into that, wondering how to troubleshoot port connectivity from the VM perspective.

I also suspect this to be the reason why glidein fails.
The VM requires a couple of TCP ports to be open.
Beside the ports that are tested within bootstrap CMS requires 1094 and 8000.

I've had port 8000 open since I started the project, but TCP/1094 was removed as I was told it was no longer needed from the LHC@Home FAQ port list
https://lhcathome.web.cern.ch/test4theory/my-firewall-complaining-which-ports-does-project-use

I've added both TCP/9094 and TCP/1094 back into my BOINC aliases list and now have a running CMS VBox task on my Win10 host. The task has been running for about an hour now and is using ~86% of a CPU. Much different from before where the task would end at <21 minutes and consume no more than 3-4% CPU.

Can the LHC@Home port listing be re-validated to ensure all used ports are on the FAQ?

I have a completed work-unit and more in progress!
https://lhcathome.cern.ch/lhcathome/result.php?resultid=334074794