Bug 2145004

Summary: On a RHEL 9 VM stopping and starting the spice-vdagentd results in a non-usable console
Product: Red Hat Enterprise Linux 8 Reporter: Frank DeLorey <fdelorey>
Component: spice-vdagentAssignee: Victor Toso <victortoso>
Status: CLOSED ERRATA QA Contact: Tomas Pelka <tpelka>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 8.6CC: tpelka, victortoso, virt-maint, zhguo
Target Milestone: rcKeywords: OtherQA, Triaged
Target Release: 8.5   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: spice-vdagent-0.20.0-5.el8 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
: 2160750 (view as bug list) Environment:
Last Closed: 2023-05-16 08:41:15 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 2160750    

Description Frank DeLorey 2022-11-22 21:38:08 UTC 
Description of problem:
Customer reported that randomly the console to their RHEL 9 VM would be stuck at "Connected to graphic server"

Version-Release number of selected component (if applicable):
RHV 4.5.2

How reproducible:
At will

Steps to Reproduce:
1.systemctl stop spice-vdagentd
2.systemctl start spice-vdagentd

Actual results:
spice-vdagent appears to start but console is stuck

Expected results:
Console should allow logins

Additional info:
I can reproduce at will on our lab system. I noticed a few errors when it happens and they change but all result in a hung console. The first time I bounced the agent one of the spice-vdagents did not enter do_pol:

[root@dhcp181-100 ~]# ps -elfL|grep spice
5 R root        2143    1805    2143 26    3  80   0 - 40354 -      15:47 ?        00:04:51 /usr/bin/spice-vdagent
1 S root        2143    1805    2149  0    3  80   0 - 40354 do_pol 15:47 ?        00:00:00 /usr/bin/spice-vdagent
1 S root        2143    1805    2282  0    3  80   0 - 40354 do_pol 15:47 ?        00:00:00 /usr/bin/spice-vdagent
1 S root        2487       1    2487  0    3  80   0 - 39924 do_pol 16:01 ?        00:00:00 /usr/sbin/spice-vdagentd
1 S root        2487       1    2489  0    3  80   0 - 39924 do_pol 16:01 ?        00:00:00 /usr/sbin/spice-vdagentd
1 S root        2487       1    2490  0    3  80   0 - 39924 futex_ 16:01 ?        00:00:00 /usr/sbin/spice-vdagentd

The second time it did not spawn the spice-vdagent process?

[root@dhcp181-100 ~]# ps -elfL|grep spice
1 S root        1920       1    1920  0    3  80   0 - 39924 do_pol 16:21 ?        00:00:00 /usr/sbin/spice-vdagentd
1 S root        1920       1    1922  0    3  80   0 - 39924 do_pol 16:21 ?        00:00:00 /usr/sbin/spice-vdagentd
1 S root        1920       1    1923  0    3  80   0 - 39924 futex_ 16:21 ?        00:00:00 /usr/sbin/spice-vdagentd


We see some errors in the messages file:

Nov 22 16:08:04 localhost spice-vdagent[1769]: vdagent started
Nov 22 16:08:04 localhost systemd[1]: spice-vdagentd.service: Can't open PID file /run/spice-vdagentd/spice-vdagentd.pid (yet?) after start: Operation not permitted
Nov 22 16:08:04 localhost spice-vdagent[1769]: warning could not get file xfer save dir, file transfers will be disabled
Nov 22 16:08:04 localhost spice-vdagent[1769]: File transfer is disabled
Nov 22 16:08:04 localhost spice-vdagentd[1772]: opening vdagent virtio channel
Nov 22 16:08:04 localhost spice-vdagent[1769]: Received Graphics Device Info:
Nov 22 16:08:04 localhost spice-vdagent[1769]: Couldn't find an XRandr output for the specified device
Nov 22 16:08:04 localhost spice-vdagent[1769]: channel_id: 0 monitor_id: 0 device_address: pci/0000/01.0, device_display_id: 0 xrandr output ID NOT FOUND
Nov 22 16:08:04 localhost spice-vdagent[1769]: Received Graphics Device Info:
Nov 22 16:08:04 localhost spice-vdagent[1769]: Couldn't find an XRandr output for the specified device
Nov 22 16:08:04 localhost spice-vdagent[1769]: channel_id: 0 monitor_id: 0 device_address: pci/0000/01.0, device_display_id: 0 xrandr output ID NOT FOUND
Nov 22 16:08:04 localhost spice-vdagent[1769]: Received Graphics Device Info:
Nov 22 16:08:04 localhost spice-vdagent[1769]: Couldn't find an XRandr output for the specified device
Nov 22 16:08:04 localhost spice-vdagent[1769]: channel_id: 0 monitor_id: 0 device_address: pci/0000/01.0, device_display_id: 0 xrandr output ID NOT FOUND
Nov 22 16:13:06 localhost kernel: traps: spice-vdagentd[1772] general protection fault ip:7f3820fb5f5f sp:7fff0b3219c0 error:0 in libc.so.6[7f3820f31000+176000]
Nov 22 16:13:06 localhost spice-vdagent[1769]: warning could not get file xfer save dir, file transfers will be disabled
Nov 22 16:13:06 localhost spice-vdagent[1769]: File transfer is disabled
Nov 22 16:13:06 localhost kernel: spice-vdagent[1769]: segfault at 0 ip 0000555adfd836f6 sp 00007ffc57aa9490 error 4 in spice-vdagent[555adfd7b000+d000]
Nov 22 16:13:09 localhost systemd-coredump[1862]: Resource limits disable core dumping for process 1769 (spice-vdagent).
Nov 22 16:13:09 localhost systemd-coredump[1862]: Process 1769 (spice-vdagent) of user 42 dumped core.
Nov 22 16:13:09 localhost systemd-coredump[1863]: Resource limits disable core dumping for process 1772 (spice-vdagentd).
Nov 22 16:13:09 localhost systemd-coredump[1863]: Process 1772 (spice-vdagentd) of user 0 dumped core.
Nov 22 16:13:09 localhost systemd[1]: spice-vdagentd.service: Main process exited, code=dumped, status=11/SEGV
Nov 22 16:13:09 localhost systemd[1]: spice-vdagentd.service: Failed with result 'core-dump'.
Nov 22 16:13:38 localhost systemd[1]: spice-vdagentd.service: Can't open PID file /run/spice-vdagentd/spice-vdagentd.pid (yet?) after start: Operation not permitted
Nov 22 16:19:14 localhost spice-vdagent[1905]: vdagent started
Nov 22 16:19:14 localhost spice-vdagent[1905]: could not connect to X-server
Nov 22 16:19:14 localhost spice-vdagentd[1883]: Error receiving data: Connection reset by peer
Nov 22 16:21:24 localhost spice-vdagentd[1883]: vdagentd quitting, returning status 0
Nov 22 16:21:24 localhost systemd[1]: spice-vdagentd.service: Deactivated successfully.
Nov 22 16:21:56 localhost systemd[1]: spice-vdagentd.service: Can't open PID file /run/spice-vdagentd/spice-vdagentd.pid (yet?) after start: Operation not permitted
Comment 2 Peter Krempa 2022-11-23 08:28:19 UTC 
Re-assigning to the 'spice' component for further investigation.

Please fill in the specific version information for the individual virtualization packages for the host and also the version of the spice-vdagent package in the guest OS.
Comment 3 Frank DeLorey 2022-11-25 16:59:23 UTC 
HOST:

OS Version: RHEL - 8.6 - 0.1.el8
OS Description: Red Hat Enterprise Linux 8.6 (Ootpa)
Kernel Version: 4.18.0 - 372.26.1.el8_6.x86_64
KVM Version: 6.2.0 - 11.module+el8.6.0+14712+f96656d3
LIBVIRT Version: libvirt-8.0.0-5.module+el8.6.0+14495+7194fa43
VDSM Version: vdsm-4.50.2.2-1.el8ev
SPICE Version: 0.14.3 - 4.el8

VM:

spice-vdagent-0.21.0-4.el9.x86_64
Comment 10 Victor Toso 2023-01-13 14:56:28 UTC 
Bug is not reproducible when backporting merge-request 42 and 46

[0] https://gitlab.freedesktop.org/spice/linux/vd_agent/-/merge_requests/42
[1] https://gitlab.freedesktop.org/spice/linux/vd_agent/-/merge_requests/46

Moving to POST.
Comment 22 errata-xmlrpc 2023-05-16 08:41:15 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (spice-vdagent bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:2885