UTM 4.3.3 Linux guest hangs on MacOS with "Error: port is not opened"

[gglluukk]

Describe the issue
UTM 4.3.3 Linux guest hangs on MacOS with "Error: port is not opened"

Configuration

• UTM Version: 4.3.3
• macOS Version: 12.6.8
• Mac Chip (Intel, M1, ...): M1

It is related to closed issue: https://github.com/utmapp/UTM/issues/5472

After upgrading to UTM 4.3.3 UTM itself doesn't crush, however virtual guest hangs on with the following error (see first picture). No external devices were attached.

UTM 4.3.0 runs without any errors.

The only 'non-standart' configuration is the following (second picture):

[neldredge-unco]

I am seeing this too, with a Windows 11 ARM guest and no serial devices on the VM. It happens while attempting to download a Windows Update (before the install begins).

I have a vague idea that it might have to do with the fact that the keyboard and mouse have been idle for a few minutes. I wondered if maybe it had something to do with the screen saver. It's not exactly that, because it doesn't always hang when the screen saver activates, but just maybe there is some connection?

[osy]

Can you try https://github.com/utmapp/UTM/suites/14668665657/artifacts/832453260 it should have more verbose logging which may help pin point the issue.

[gglluukk]

OK, running it now under maximum load but error isn't predictable, it happens randomly, so let's see

[neldredge-unco]

I got it to hang with the debug build: debug.log

The hang occurs first. When I attempt to halt the VM is when the "Error: port is not opened" dialog pops up. I think it actually popped up two identical dialogs on top of each other, because I had to dismiss it twice.

After that, the VM is off (gray window with the play button) but the window can't be closed. The red close button is grayed out, and the minimize and maximize buttons don't do anything. It only goes away when you quit UTM.

Snippet from the log:

2023-07-29 19:04:55,663 DEBUG (null)-/Users/runner/Library/Developer/Xcode/DerivedData/UTM-gnwjeapbifchcjczzvitjgckdhnq/SourcePackages/checkouts/CocoaSpice/Sources/CocoaSpice/CSDisplay.m:207 [CocoaSpice] cs_gl_draw
qemu-aarch64-softmmu: warning: Spice: playback:0 (0x14a0d9910): channel->thread_id (0x1df886080) != pthread_self (0x16daa7000).If one of the threads is != io-thread && != vcpu-thread, this might be a BUG
qemu-aarch64-softmmu: warning: Spice: record:0 (0x14a0d99b0): channel->thread_id (0x1df886080) != pthread_self (0x16daa7000).If one of the threads is != io-thread && != vcpu-thread, this might be a BUG
Debug JSON recieved <- {
    data =     {
        client =         {
            family = unix;
            host = "";
            port = "";
        };
        server =         {
            family = unix;
            host = "";
            port = "";
        };
    };
    event = "SPICE_DISCONNECTED";
    timestamp =     {
        microseconds = 944584;
        seconds = 1690679185;
    };
}
Debug JSON recieved <- {
    data =     {
        client =         {
            family = unix;
            host = "";
            port = "";
        };
        server =         {
            family = unix;
            host = "";
            port = "";
        };
    };
    event = "SPICE_DISCONNECTED";
    timestamp =     {
        microseconds = 944675;
        seconds = 1690679185;
    };
}
2023-07-29 19:06:26,069 DEBUG (null)-/Users/runner/Library/Developer/Xcode/DerivedData/UTM-gnwjeapbifchcjczzvitjgckdhnq/SourcePackages/checkouts/CocoaSpice/Sources/CocoaSpice/CSConnection.m:138 [CocoaSpice] SPICE agent connected: 0
2023-07-29 19:06:26,072 MESSAGE (null)-main channel: closed
2023-07-29 19:06:26,073 DEBUG (null)-/Users/runner/Library/Developer/Xcode/DerivedData/UTM-gnwjeapbifchcjczzvitjgckdhnq/SourcePackages/checkouts/CocoaSpice/Sources/CocoaSpice/CSConnection.m:278 zap inputs channel
2023-07-29 19:06:26,073 DEBUG (null)-/Users/runner/Library/Developer/Xcode/DerivedData/UTM-gnwjeapbifchcjczzvitjgckdhnq/SourcePackages/checkouts/CocoaSpice/Sources/CocoaSpice/CSConnection.m:287 zap audio channel
2023-07-29 19:06:26,074 DEBUG (null)-/Users/runner/Library/Developer/Xcode/DerivedData/UTM-gnwjeapbifchcjczzvitjgckdhnq/SourcePackages/checkouts/CocoaSpice/Sources/CocoaSpice/CSConnection.m:273 zap display channel (#0)
2023-07-29 19:06:26,075 DEBUG (null)-/Users/runner/Library/Developer/Xcode/DerivedData/UTM-gnwjeapbifchcjczzvitjgckdhnq/SourcePackages/checkouts/CocoaSpice/Sources/CocoaSpice/CSConnection.m:265 [CocoaSpice] cs_channel_destroy:265
2023-07-29 19:06:26,075 DEBUG (null)-/Users/runner/Library/Developer/Xcode/DerivedData/UTM-gnwjeapbifchcjczzvitjgckdhnq/SourcePackages/checkouts/CocoaSpice/Sources/CocoaSpice/CSConnection.m:266 zap main channel
Debug JSON send -> {
    execute = "query-mice";
}
2023-07-29 19:07:18,942 WARNING (null)-[CocoaSpice] The port is not opened
QMP stream error seen: Error Domain=com.utmapp.QEMUKit Code=-1 "The port is not opened" UserInfo={NSLocalizedDescription=The port is not opened}
RPC: The port is not opened
Debug JSON send -> {
    execute = "query-mice";
}
2023-07-29 19:07:18,948 WARNING (null)-[CocoaSpice] The port is not opened
QMP stream error seen: Error Domain=com.utmapp.QEMUKit Code=-1 "The port is not opened" UserInfo={NSLocalizedDescription=The port is not opened}
RPC: The port is not opened
Debug JSON send -> {
    execute = "query-mice";
}
2023-07-29 19:07:18,957 WARNING (null)-[CocoaSpice] The port is not opened
QMP stream error seen: Error Domain=com.utmapp.QEMUKit Code=-1 "The port is not opened" UserInfo={NSLocalizedDescription=The port is not opened}
RPC: The port is not opened
Debug JSON send -> {
    execute = "query-mice";
}

[gglluukk]

debug.log

[osy]

This build has even more logging from the QEMU side since I am still not able to figure out what's causing the issue: https://github.com/utmapp/UTM/suites/14676612107/artifacts/833073067

[gglluukk]

debug.log hope this one will help

[osy]

Curious if disabling audio (vm settings -> right click sound device -> delete) will change anything?

[gglluukk]

ok, i'll try

[neldredge-unco]

I reproduced using https://github.com/utmapp/UTM/suites/14676612107/artifacts/833073067 : debug.log. I'll try deleting the sound device now.

[neldredge-unco]

It still hung with the sound device removed.
debug.log config.plist.txt

[gglluukk]

same here: debug.log

[osy]

Can either of you share the VM with me? You can email osy at turing dot llc.

[gglluukk]

that's kind of problematic for me since i need to clean it deeply from working projects in there and all its artifacts. @neldredge-unco ?

[osy]

One more test: uninstall spice-vdagent and see if that makes a difference

[gglluukk]

I don't have it on MacOS host:

me@mika ~ $ find /Applications/UTM-4.3.3.app/ -name spice-vdagent
me@mika ~ $ locate spice-vdagent

as well it's not installed in Linux guest:

lab ~ # locate spice-vdagent
/var/db/repos/gentoo/app-emulation/spice-vdagent
/var/db/repos/gentoo/app-emulation/spice-vdagent/Manifest
/var/db/repos/gentoo/app-emulation/spice-vdagent/files
/var/db/repos/gentoo/app-emulation/spice-vdagent/metadata.xml
/var/db/repos/gentoo/app-emulation/spice-vdagent/spice-vdagent-0.22.1.ebuild
/var/db/repos/gentoo/app-emulation/spice-vdagent/files/spice-vdagent.confd-2
/var/db/repos/gentoo/app-emulation/spice-vdagent/files/spice-vdagent.initd-4
/var/db/repos/gentoo/metadata/md5-cache/app-emulation/spice-vdagent-0.22.1
lab ~ # which spice-vdagent
which: no spice-vdagent in (/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/root/mitigation:/root/scripts:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/opt/bin:/mnt/linux/go/bin/:~/.local/bin/)
lab ~ # ps ax | grep [s]pice-vdagent

[osy]

Okay, that makes sense, nvm

[neldredge-unco]

My test case starts with the Windows 11 VHDX from build 25346, dated 20230506 (which I happen to have on my disk already, instead of downloading the latest). I followed the install procedure at https://gist.github.com/wrmack/29d580a0bd665bace21609d5ef675ba1 , skipping the LabConfig registry key but still doing the WindowsSelfHost ones, and skipping step 6.

The hang always occurs when doing Windows Update for the first time, during the download of the new build, but always at a different percent. That's also the first time in the process when I leave it unattended for several minutes. In every test, I've gone away at that point, and when I come back and unlock the screen saver, it's hung. I have it on AC power so I don't think the machine would be sleeping during that time, but I'm not completely familiar with how Mac power management works.

When I have some time in the next few days, I can try to reproduce starting from a fresh install, and I'll screen record it. I can also submit the entire VM if it would help, but I'm on a 20 Mbps link so it would take a while to upload.

I might also test whether the hang still occurs if I keep using the VM and moving the mouse, instead of walking away.

[osy]

Okay, one more build with even MORE verbose logging. https://github.com/utmapp/UTM/suites/14679241836/artifacts/833192468

[gglluukk]

debug.log.gz

[osy]

@neldredge-unco @gglluukk How much RAM is your computer configured with? How much free storage?

[gglluukk]

lab ~ # free
               total        used        free      shared  buff/cache   available
Mem:         4032896      132600     3782184         728      118112     3769516
Swap:              0           0           0
lab ~ # df
Filesystem      Size  Used Avail Use% Mounted on
none            2.0G  656K  2.0G   1% /run
udev             10M     0   10M   0% /dev
tmpfs           2.0G     0  2.0G   0% /dev/shm
/dev/vda2        15G  9.5G  4.3G  70% /
cgroup_root      10M     0   10M   0% /sys/fs/cgroup

[osy]

I'm wondering about your host Mac

[gglluukk]

RAM: 8 GB HDD: Total 245 GB, Free: 62 GB

[osy]

Duplicate of #5489

[osy]

Confirmed this is the same issue. Follow #5489 for progress.

[osy]

Please try https://github.com/utmapp/UTM/suites/14685729939/artifacts/833666921

[neldredge-unco]

https://github.com/utmapp/UTM/suites/14685729939/artifacts/833666921 fixes the problem for me too. Thanks!

By the way, my Mac has 16 GB memory and 100+ GB storage free, and the VM is assigned 11 GB memory and 64 GB storage.