VBoxManage.exe: error: Waiting for guest process failed: The specified user was not able to logon on guest

[darkguy2008]

Hi, first time submitting a bug here, sorry if I'm doing it wrong beforehand.

Anyways, I've found a way to run some commands in the guest system by using VBoxManage.exe and so far it works well, but then it stops working after some time.

I'm using the instructions I made here: ​https://darkguy2008.github.io/VBoxWSL2/virtualbox-automatic-port-forward/ most notably, the problem seems to be in this line:

$netstatOutput = & $VBOXMANAGE guestcontrol $VMNAME run --username $USER --password $PASS "/usr/bin/sudo" -- "/usr/bin/netstat" "-ant"

I've tried both with a normal user, or a root user, and the problem persists.

Host is Windows 11 22000.613 Guest is Ubuntu 21.10 (Minimized), installed Guest Additions, and that's it.

The full error is:

VBoxManage.exe: error: Waiting for guest process failed: The specified user was not able to logon on guest VBoxManage.exe: error: Details: code VBOX_E_IPRT_ERROR (0x80bb0005), component GuestSessionWrap, interface IGuestSession, callee IUnknown VBoxManage.exe: error: Context: "WaitForArray(ComSafeArrayAsInParam(aSessionWaitFlags), 30 * 1000, &enmWaitResult)" at line 893 of file VBoxManageGuestCtrl.cpp

Restarting the vboxadd & vboxadd-service services in the guest fixes the problem if I do that frequently, but then it's not an option because that makes shared folders stop working.

It doesn't make much sense that it works correctly for some iterations and then it stops working at all after some time. So I'm filing it as a bug.

[darkguy2008]

Adding some more context, I just found this when running:

systemctl status vboxadd-service.service:

Apr 15 18:09:17 wsl systemd[1]: Starting vboxadd-service.service...
Apr 15 18:09:17 wsl vboxadd-service[1160]: vboxadd-service.sh: Starting VirtualBox Guest Addition service.
Apr 15 18:09:17 wsl vboxadd-service.sh[1164]: Starting VirtualBox Guest Addition service.
Apr 15 18:09:17 wsl systemd[1]: Started vboxadd-service.service.
Apr 15 18:09:48 wsl VBoxService[1171]: pam_loginuid(login:session): Error writing /proc/self/loginuid: Operation not permitted
Apr 15 18:09:48 wsl VBoxService[1171]: pam_loginuid(login:session): set_loginuid failed
Apr 15 18:09:48 wsl VBoxService[1171]: pam_unix(login:session): session opened for user root by (uid=0)

Or basically:

VBoxService[1171]: pam_loginuid(login:session): Error writing /proc/self/loginuid: Operation not permitted

VBoxService[1171]: pam_loginuid(login:session): set_loginuid failed

I hope this helps to figure out the problem :)

[darkguy2008]

After a while, using journalctl, I was able to find some more context. It seems there's a problem with shared files?

Apr 15 22:13:01 wsl VBoxService[1183]: pam_unix(login:session): session closed for user root
Apr 15 22:13:02 wsl VBoxService[1183]: pam_unix(login:session): session opened for user root by (uid=0)
Apr 15 22:13:02 wsl VBoxService[1183]: pam_unix(login:session): session closed for user root
Apr 15 22:13:04 wsl VBoxService[1183]: pam_unix(login:session): session opened for user root by (uid=0)
Apr 15 22:13:04 wsl VBoxService[1183]: pam_unix(login:session): session closed for user root
Apr 15 22:13:05 wsl VBoxService[1183]: pam_unix(login:session): session opened for user root by (uid=0)
Apr 15 22:13:05 wsl VBoxService[1183]: pam_unix(login:session): session closed for user root
Apr 15 22:13:06 wsl VBoxService[1183]: PAM unable to dlopen(pam_unix.so): /lib/security/pam_unix.so: cannot open shared object file: Too many open files
Apr 15 22:13:06 wsl VBoxService[1183]: PAM adding faulty module: pam_unix.so
Apr 15 22:13:06 wsl VBoxService[1183]: PAM unable to dlopen(pam_deny.so): /lib/security/pam_deny.so: cannot open shared object file: Too many open files
Apr 15 22:13:06 wsl VBoxService[1183]: PAM adding faulty module: pam_deny.so
Apr 15 22:13:06 wsl VBoxService[1183]: PAM unable to dlopen(pam_permit.so): /lib/security/pam_permit.so: cannot open shared object file: Too many open files
Apr 15 22:13:06 wsl VBoxService[1183]: PAM adding faulty module: pam_permit.so
Apr 15 22:13:06 wsl VBoxService[1183]: PAM unable to dlopen(pam_cap.so): /lib/security/pam_cap.so: cannot open shared object file: Too many open files
Apr 15 22:13:06 wsl VBoxService[1183]: PAM adding faulty module: pam_cap.so
Apr 15 22:13:06 wsl VBoxService[1183]: PAM unable to dlopen(pam_umask.so): /lib/security/pam_umask.so: cannot open shared object file: Too many open files
Apr 15 22:13:06 wsl VBoxService[1183]: PAM adding faulty module: pam_umask.so
Apr 15 22:13:06 wsl VBoxService[1183]: PAM unable to dlopen(pam_systemd.so): /lib/security/pam_systemd.so: cannot open shared object file: Too many open files
Apr 15 22:13:06 wsl VBoxService[1183]: PAM adding faulty module: pam_systemd.so
Apr 15 22:13:06 wsl VBoxService[1183]: PAM unable to dlopen(pam_gnome_keyring.so): /lib/security/pam_gnome_keyring.so: cannot open shared object file: Too many open files
Apr 15 22:13:06 wsl VBoxService[1183]: PAM adding faulty module: pam_gnome_keyring.so
Apr 15 22:13:09 wsl VBoxService[1183]: PAM unable to dlopen(pam_unix.so): /lib/security/pam_unix.so: cannot open shared object file: Too many open files
Apr 15 22:13:09 wsl VBoxService[1183]: PAM adding faulty module: pam_unix.so
Apr 15 22:13:09 wsl VBoxService[1183]: PAM unable to dlopen(pam_deny.so): /lib/security/pam_deny.so: cannot open shared object file: Too many open files
Apr 15 22:13:09 wsl VBoxService[1183]: PAM adding faulty module: pam_deny.so
Apr 15 22:13:09 wsl VBoxService[1183]: PAM unable to dlopen(pam_permit.so): /lib/security/pam_permit.so: cannot open shared object file: Too many open files
Apr 15 22:13:09 wsl VBoxService[1183]: PAM adding faulty module: pam_permit.so
Apr 15 22:13:09 wsl VBoxService[1183]: PAM unable to dlopen(pam_cap.so): /lib/security/pam_cap.so: cannot open shared object file: Too many open files
Apr 15 22:13:09 wsl VBoxService[1183]: PAM adding faulty module: pam_cap.so
Apr 15 22:13:09 wsl VBoxService[1183]: PAM unable to dlopen(pam_umask.so): /lib/security/pam_umask.so: cannot open shared object file: Too many open files
Apr 15 22:13:09 wsl VBoxService[1183]: PAM adding faulty module: pam_umask.so
Apr 15 22:13:09 wsl VBoxService[1183]: PAM unable to dlopen(pam_systemd.so): /lib/security/pam_systemd.so: cannot open shared object file: Too many open files
Apr 15 22:13:09 wsl VBoxService[1183]: PAM adding faulty module: pam_systemd.so

And it keeps repeating until I stop the process that calls VBoxManage.exe.

So, it seems something is fishy between VBoxManage, PAM and the way it opens or closes user sessions. Again, restarting both vboxadd and vboxadd-service services make it work, so maybe there's something in that service locking files in a way that PAM doesn't like it.

I also tried to disable pam_loginuid.so in both login and ssh files, with no avail. This line:

session    required     pam_loginuid.so

There's some hints around the net with these error messages related to reading/writing to the loginuid file from different threads. Dunno if it helps.

Maybe it's related to kernel? ​https://blog.clanzx.net/software/cronie.html

---

More updates:

Disabling the pam_loginuid.so in all files inside /etc/pam.d, and disabling the AppArmor service by running:

sudo systemctl disable apparmor

Seems to have fixed the problem.

There's definitely something going on with the VBoxManage app though.

[darkguy2008]

More updates:

No, removing pam_loginuid.so and disabling AppArmor doesn't work...

[galitsyn]

Thank you for reporting the issue. It should be fixed in VirtualBox 6.1.36. Please refer to https://www.virtualbox.org/wiki/Downloads page.