Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: Reliably start vmware-user-suid-wrapper #670

Open
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

polarathene
Copy link

@polarathene polarathene commented Jun 5, 2023

Adapted from findings: #568 (comment)

Related: #669 systemd/systemd#27919
Fixes: #568 #603 #604 #627 #629 #657

UPDATE: Reviewers may want to skip to this comment as a starting point, it'll save you time 👍

UPDATE 2: Should be fixed by upstream systemd change for v254: systemd/systemd#28314

Background

Via https://pagure.io/fedora-kde/SIG/issue/50 and some hunting in the links it seems as if systemd 248 as shipped with F34 (systemd-248-2.fc34.x86_64) and forking are an unhappy mix - the way I read it, systemd 248 looks at the exit status of the process referenced in the .desktop file - and then, in an act of cleaning up the user unit, kills any and all processes that were part of the process tree of that user unit. - Source

@ravindravmw was involved in the quoted bug report ending the discussion with:

Systemd 250.x introduces ExitType=cgroup which is used by KDE and should address this bug.

  • In F34 and F35, ExitType is not present in /run/user/1000/systemd/generator.late/app-vmware\x2duser.
  • In Rawhide upgraded system /run/user/1000/systemd/generator.late/app-vmware\x2duser has ExitType=cgroup.

We also verified that vmusr process is started, copy&paste works as expected.
There is no change needed in open-vm-tools. So, closing it. - Source

ExitType=cgroup (systemd v250 Dec 2021) does not appear to be sufficient however. Many report the generated service (for XDG autostart vmware-user.desktop via systemd-xdg-autostart-generator) frequently encounters the TimeoutSec=5s, which still terminates the child process losing the functionality it provides.

Description

UPDATE: As later commented below, the related systemd bug report I raised will prevent the timeout issue being triggered for anyone with an upcoming systemd release with that fix.

Thus the changes proposed by this PR may not be relevant to review and accept anymore. I tried to investigate what might cause the race condition for vmware-user-suid-wrapper to not be recognized as "Started" by systemd. Although I could reliably produce a failure or success, I was unsuccessful at pin-pointing the cause.

With the systemd adjustment to their systemd-xdg-autostart-generator, the timeout termination will only be applicable to stopping a service, I doubt it's worth anyones time to investigate further 🤷‍♂️


Original Content (Click to expand)

The timeout can be extended, but only delays termination. Whatever the cause is, it happens early where the service does not detect itself as "Started", only the intitial "Starting" state is logged (see example).

It may be related to the exit status of vmware-user-suid-wrapper or some sort of race condition?

Proposed Solution - Explicit unit with opt-out from generated service

A custom key can be included in the .desktop file which systemd will recognize to ignore generating a service config file.

An explicit service config can then be enabled that follows the convention guidelines for XDG DE Integration. It should be placed in /usr/lib/systemd/user/.

I found a near duplicate of the generated service was less likely to encounter the failure, but still possible. It appears to be due to Type=exec, changing to Type=forking seems to avoid the problem and from the systemctl --user status output looks more appropriate.

Alternative Solution - Override the generated unit

Simply adding a blank override, I was unable to reproduce the failure. If it is a race condition, it seems rather sensitive to however an override affects the scheduling. While I could not reproduce the failure, I would not rely on an empty override side-effect.

Instead, overriding the Type=exec to Type=forking should be sufficient, or removing the timeout with TimeoutSec=.

The location can be one of the supported user unit locations, with an override config dir + file. It is simpler, and does not need to tamper with the .desktop file.

Additional Info

Unlike the .desktop file this PR specifies a fixed path to the binary for ExecStart=. If preferable it could mimic the template approach with .desktop that is adjusted by Makefile.am, or leave this up to packagers that opt-in to copy this config to the system?

I have seen that Arch Linux open-vm-tools package provides two .service files (like other distros), and copies these in their PKGBUILD. This one differs as I've referenced the XDG generated service (conventions for naming and assigning to the app.slice, and notably as a user unit), I am not sure if that's the intention since this 2018 commit message for main.c Wayland DnD support seems to imply an expectation of being run as root to correctly function?

If the alternative solution above is preferred, then there is no ExecStart= value to be concerned with, but the override dir + file may not be as friendly? (app-vmware\x2duser@autostart.service.d/override.conf)

Additionally:

  • I chose Type=forking which seemed to be appropriate due to the fork() where the command completes quickly but continues to run a process in the background. However while the systemd docs seem to encourage this, they also encourage referencing a PIDFile that AFAIK isn't produced?
  • Type=exec with ExitType=cgroup (which the generated service configured) is viable, but the systemd service docs seem to discourage leaning on ExitType=cgroup if possible, it's only used in the XDG autostart generator since it cannot infer what would be more appropriate (EDIT: this pairing seems to be related to the bug).

Alternatives considered

This issue is likely specific to the systemd generator being relied on by a distro / DE. The proposed fix seems most appropriate.

The .desktop config could instead Exec= a very simple shell script which also seems to work (presumably because the shell script becomes the main process and thus the wrapper exit status doesn't mislead the service to be terminated):

#! /bin/sh
/usr/bin/vmware-user-suid-wrapper

As the .desktop unit is over a decade old, I have the impression it's not exactly ideal for this service, especially for modern distros that ship with systemd? I assume that it's intended to delay starting until some additional context is available, such as the for the X11/Wayland detection? (this comment seems to infer this importance for other projects)

Semi-related activity

A similar solution was applied to workaround a Gnome autostart key in .desktop preventing service generation by systemd (while the KDE equivalent does not have that affect):

  • Bug report (Feb 2021)
  • Fix (Sep 2022)
  • Some other software is discussed as not working as well, one of the .desktop shared does not have a Gnome key, and would likely have the same issue VMware has here. Another comment highlights a concern with forking behaviour that accidentally triggers the process being killed by systemd.

The upstream systemd bug for the Gnome autostart key ignore behaviour was resolved in April 2023 (unrelated to VMWare issue). It has some comments which highlight that the generator feature can provide some compatibility, but that projects should ideally migrate to proper systemd services:

I still think that we just need to go through the migration pain here. We can provide some compatibility, but certain services just need to be migrated to systemd proper for their integration to work - systemd/systemd#18791 (comment)

In KDE we had an X-KDE-autostart-phase=

It was only used by a few core critical processes, our stance was that if it's so important that it needs custom startup positioning it needs to have a custom service file where we can express the exact wants/before/afters. - systemd/systemd#18791 (comment)


Refs

systemd XDG autostart + user units:

.desktop:

When the system manages XDG autostart `.desktop` files via systemd-xdg-autostart-generator, the generated service for `vmware-user.desktop` frequently times out, failing to initialize.

A custom key can be included in the `.desktop` file which systemd will recognize to ignore generating a service config file.

An explicit service config can then be enabled that follows the [convention guidelines for XDG DE Integration](https://systemd.io/DESKTOP_ENVIRONMENTS/#xdg-standardization-for-applications). It should be placed in `/usr/lib/systemd/user/`.
@polarathene

This comment was marked as outdated.

@vmwclabot
Copy link
Member

@polarathene, VMware has approved your signed contributor license agreement.

@polarathene
Copy link
Author

polarathene commented Jun 9, 2023

Increasing the VM guest from 2 vCPU to 4 on my system was effective at increasing the host CPU load often to 100% and stalling responsiveness with UI interactions for brief periods. Reproducing the failure was quite reliable from this change.


Related implicit startup dependency - AT-SPI?

Notes (Click to expand)

I browsed the journalctl -b logs around the failure time and looked into at-spi-bus-launcher which was activated via DBus request (from the vmtoolsd -n vmusr command that the failing unit ran):

Service status logs
# custom unit active instead of generated one:
$ systemctl --user status vmware-user

× vmware-user.service - VMware User Agent
     Loaded: loaded (/etc/xdg/autostart/vmware-user.desktop; enabled; preset: enabled)
     Active: failed (Result: timeout) since Wed 2023-06-07 17:34:46 NZST; 2min 41s ago
       Docs: man:systemd-xdg-autostart-generator(8)
    Process: 946 ExecStart=/usr/bin/vmware-user-suid-wrapper (code=exited, status=0/SUCCESS)
   Main PID: 946 (code=exited, status=0/SUCCESS)
        CPU: 437ms

Jun 07 17:34:40 polarathene systemd[600]: Starting VMware User Agent...
Jun 07 17:34:42 polarathene vmtoolsd[947]: gtk_disable_setlocale() must be called before gtk_init()
Jun 07 17:34:46 polarathene systemd[600]: vmware-user.service: start operation timed out. Terminating.
Jun 07 17:34:46 polarathene systemd[600]: vmware-user.service: Failed with result 'timeout'.
Jun 07 17:34:46 polarathene systemd[600]: Failed to start VMware User Agent.


$ systemctl --user status at-spi-dbus-bus.service

● at-spi-dbus-bus.service - Accessibility services bus
     Loaded: loaded (/usr/lib/systemd/user/at-spi-dbus-bus.service; static)
     Active: active (running) since Wed 2023-06-07 17:34:38 NZST; 3min 13s ago
   Main PID: 692 (at-spi-bus-laun)
      Tasks: 10 (limit: 4624)
     Memory: 3.2M
        CPU: 84ms
     CGroup: /user.slice/user-1000.slice/user@1000.service/session.slice/at-spi-dbus-bus.service
             ├─ 692 /usr/lib/at-spi-bus-launcher
             ├─1037 /usr/bin/dbus-daemon --config-file=/usr/share/defaults/at-spi2/accessibility.conf --nofork --print-address 11 --address=unix:path=/run/user/1000/at-spi/bus_0
             └─1050 /usr/lib/at-spi2-registryd --use-gnome-session

Jun 07 17:34:38 polarathene systemd[600]: Starting Accessibility services bus...
Jun 07 17:34:38 polarathene systemd[600]: Started Accessibility services bus.
Jun 07 17:34:42 polarathene at-spi-bus-launcher[1037]: dbus-daemon[1037]: Activating service name='org.a11y.atspi.Registry' requested by ':1.0' (uid=1000 pid=947 comm="/usr/bin/vmtoolsd -n vmusr --blockFd 3")
Jun 07 17:34:42 polarathene at-spi-bus-launcher[1037]: dbus-daemon[1037]: Successfully activated service 'org.a11y.atspi.Registry'
Jun 07 17:34:42 polarathene at-spi-bus-launcher[1050]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.Registry


$ systemctl --user cat at-spi-dbus-bus.service

# /usr/lib/systemd/user/at-spi-dbus-bus.service
[Unit]
Description=Accessibility services bus
PartOf=graphical-session.target

[Service]
Type=dbus
BusName=org.a11y.Bus
ExecStart=/usr/lib/at-spi-bus-launcher
Slice=session.slice
TimeoutStopSec=5

The DBus call starts at the same time the GTK log line appears. We know that the related functionality like DnD and Copy/Paste are handled by open-vm-tools with GTK related code behind the scenes and it seems to invoke this (EDIT: Further inspection, this is possibly just part of gtk_init() and preventing the at-spi processes from being started doesn't appear to break copy/paste functionality at least).

This service is for the at-spi2-core project:

This repository contains the DBus interface definitions for AT-SPI (Assistive Technology Service Provider Interface) — the core of an accessibility stack for free software systems

  • bus - Launcher for the session's accessibility bus; see its README.md for details.
  • registryd - Daemon that keeps track of accessible applications in the user's session, and lets them talk to each other and to assistive technologies (ATs) like screen readers.

Side-note: at-spi2-registryd --use-gnome-session is used which may have some additional GNOME integration? Which may explain why GNOME on Wayland has improved compatibility 🤷‍♂️

Based on the README for the bus, and log activity it looks like this interaction is occurring with vmware-vmblock-fuse?:

`journalctl --boot --unit vmware-vmblock-fuse`

This is from a later run that was successful, but the exchange seems the same regardless (at least initially, a failure has a RELEASE opcode after the READ).

Jun 07 18:34:47 polarathene systemd[1]: Started Open Virtual Machine Tools (vmware-vmblock-fuse).
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]: FUSE library version: 3.14.1
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]: nullpath_ok: 0
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]: unique: 2, opcode: INIT (26), nodeid: 0, insize: 104, pid: 0
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]: INIT: 7.38
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]: flags=0x73fffffb
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]: max_readahead=0x00020000
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]:    INIT: 7.31
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]:    flags=0x4040f039
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]:    max_readahead=0x00020000
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]:    max_write=0x00100000
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]:    max_background=0
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]:    congestion_threshold=0
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]:    time_gran=1
Jun 07 18:34:47 polarathene vmware-vmblock-fuse[407]:    unique: 2, success, outsize: 80
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]: unique: 4, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 951
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]: getattr[NULL] /
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]:    unique: 4, success, outsize: 120
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]: unique: 6, opcode: LOOKUP (1), nodeid: 1, insize: 44, pid: 951
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]: LOOKUP /dev
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]: getattr[NULL] /dev
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]:    NODEID: 2
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]:    unique: 6, success, outsize: 144
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]: unique: 8, opcode: OPEN (14), nodeid: 2, insize: 48, pid: 951
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]: open flags: 0x8002 /dev
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]:    open[140251754401776] flags: 0x8002 /dev
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]:    unique: 8, success, outsize: 32
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]: unique: 10, opcode: FLUSH (25), nodeid: 2, insize: 64, pid: 329
Jun 07 18:34:52 polarathene vmware-vmblock-fuse[407]:    unique: 10, error: -38 (Function not implemented), outsize: 16
Jun 07 18:34:53 polarathene vmware-vmblock-fuse[407]: unique: 12, opcode: READ (15), nodeid: 2, insize: 80, pid: 951
Jun 07 18:34:53 polarathene vmware-vmblock-fuse[407]: read[140251754401776] 18 bytes from 0 flags: 0x8002
Jun 07 18:34:53 polarathene vmware-vmblock-fuse[407]:    read[140251754401776] 18 bytes from 0
Jun 07 18:34:53 polarathene vmware-vmblock-fuse[407]:    unique: 12, success, outsize: 34
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: unique: 14, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 1208
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: getattr[NULL] /
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]:    unique: 14, success, outsize: 120
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: unique: 16, opcode: OPENDIR (27), nodeid: 1, insize: 48, pid: 1208
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]:    unique: 16, success, outsize: 32
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: unique: 18, opcode: READDIRPLUS (44), nodeid: 1, insize: 80, pid: 1208
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: readdirplus[0] from 0
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]:    unique: 18, success, outsize: 824
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: unique: 20, opcode: READDIR (28), nodeid: 1, insize: 80, pid: 1208
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]:    unique: 20, success, outsize: 16
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: unique: 22, opcode: RELEASEDIR (29), nodeid: 1, insize: 64, pid: 0
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]:    unique: 22, success, outsize: 16
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: unique: 24, opcode: OPENDIR (27), nodeid: 1, insize: 48, pid: 1208
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]:    unique: 24, success, outsize: 32
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: unique: 26, opcode: GETATTR (3), nodeid: 1, insize: 56, pid: 1208
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: getattr[NULL] /
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]:    unique: 26, success, outsize: 120
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: unique: 28, opcode: READDIRPLUS (44), nodeid: 1, insize: 80, pid: 1208
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: readdirplus[0] from 0
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]:    unique: 28, success, outsize: 824
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: unique: 30, opcode: READDIR (28), nodeid: 1, insize: 80, pid: 1208
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]:    unique: 30, success, outsize: 16
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]: unique: 32, opcode: RELEASEDIR (29), nodeid: 1, insize: 64, pid: 0
Jun 07 18:35:00 polarathene vmware-vmblock-fuse[407]:    unique: 32, success, outsize: 16

Desktop XDG autostart files

Notes (Click to expand)

/etc/xdg/autostart/at-spi-dbus-bus.desktop:

[Desktop Entry]
Type=Application
Name=AT-SPI D-Bus Bus
Exec=/usr/lib/at-spi-bus-launcher --launch-immediately
OnlyShowIn=GNOME;Unity;
NoDisplay=true
AutostartCondition=GSettings org.gnome.desktop.interface toolkit-accessibility
X-GNOME-AutoRestart=true
X-GNOME-Autostart-Phase=Initialization

KDE Plasma won't have a unit generated for this (otherwise systemctl --user status "app-at\x2dspi\x2ddbus\x2dbus@autostart.service" would be successful). This .desktop file is referenced in the bus README where it mentions when at-spi-bus-launcher --launch-immediately is appropriate.

I assume VMware is using a11y functionality through this service to support it's features? If so perhaps the timing is important, but without this as the README link documents, the service will be started on-demand which for services like a Screen Reader is apparently not ideal, thus probably the same for VMware here.

/etc/xdg/autostart/kaccess.desktop:

[Desktop Entry]
Type=Application
Name=Accessibility
# ... Localization for Name
NoDisplay=true
Exec=kaccess
X-DBUS-StartupType=None
X-KDE-autostart-phase=0
OnlyShowIn=KDE

This service is generated only for KDE Plasma, and we can see that it's time stamp is aligned with the vmware-vmblock-fuse logs for when vmware-user-suid-wrapper child process would output it's GTK log (vmtoolsd -n vmuser --blockFd 3).

More explicit dependency order on SPI reliably succeeds

Logs + Config (Click to expand)
Service status logs
$ systemctl --user status "app-kaccess@autostart.service"

● app-kaccess@autostart.service - Accessibility
     Loaded: loaded (/etc/xdg/autostart/kaccess.desktop; generated)
     Active: active (running) since Wed 2023-06-07 18:34:52 NZST; 2h 4min ago
       Docs: man:systemd-xdg-autostart-generator(8)
    Process: 921 ExecCondition=/usr/lib/systemd/systemd-xdg-autostart-condition KDE  (code=exited, status=0/SUCCESS)
   Main PID: 937 (kaccess)
      Tasks: 3 (limit: 4624)
     Memory: 19.2M
        CPU: 942ms
     CGroup: /user.slice/user-1000.slice/user@1000.service/app.slice/app-kaccess@autostart.service
             └─937 /usr/bin/kaccess

Jun 07 18:34:52 polarathene systemd[603]: Starting Accessibility...
Jun 07 18:34:52 polarathene systemd[603]: Started Accessibility.
Jun 07 18:34:52 polarathene kaccess[937]: Xlib XKB extension major= 1  minor= 0
Jun 07 18:34:53 polarathene kaccess[937]: X server XKB extension major= 1  minor= 0

# custom unit active instead of generated one:
$ systemctl --user status vmware-user
● vmware-user.service - VMware User Agent
     Loaded: loaded (/etc/xdg/autostart/vmware-user.desktop; enabled; preset: enabled)
     Active: active (running) since Wed 2023-06-07 18:34:52 NZST; 2h 6min ago
       Docs: man:systemd-xdg-autostart-generator(8)
    Process: 941 ExecStart=/usr/bin/vmware-user-suid-wrapper (code=exited, status=0/SUCCESS)
   Main PID: 941 (code=exited, status=0/SUCCESS)
      Tasks: 4 (limit: 4624)
     Memory: 36.5M
        CPU: 2min 1.350s
     CGroup: /user.slice/user-1000.slice/user@1000.service/app.slice/vmware-user.service
             └─951 /usr/bin/vmtoolsd -n vmusr --blockFd 3

Jun 07 18:34:52 polarathene systemd[603]: Starting VMware User Agent...
Jun 07 18:34:52 polarathene systemd[603]: Started VMware User Agent.
Jun 07 18:34:53 polarathene vmtoolsd[951]: gtk_disable_setlocale() must be called before gtk_init()

# custom unit above modified to depend on registryd being ready first (via custom spi.service)
# the spi.service then depends on the at-spi-dbus-bus.service being started before it:
$ systemctl --user status at-spi-dbus-bus.service

● at-spi-dbus-bus.service - Accessibility services bus
     Loaded: loaded (/usr/lib/systemd/user/at-spi-dbus-bus.service; static)
     Active: active (running) since Wed 2023-06-07 18:34:50 NZST; 2h 11min ago
   Main PID: 689 (at-spi-bus-laun)
      Tasks: 6 (limit: 4624)
     Memory: 1.9M
        CPU: 368ms
     CGroup: /user.slice/user-1000.slice/user@1000.service/session.slice/at-spi-dbus-bus.service
             ├─689 /usr/lib/at-spi-bus-launcher
             └─957 /usr/bin/dbus-daemon --config-file=/usr/share/defaults/at-spi2/accessibility.conf --nofork --print-address 11 --address=unix:path=/run/u>

Jun 07 18:34:50 polarathene systemd[603]: Starting Accessibility services bus...
Jun 07 18:34:50 polarathene systemd[603]: Started Accessibility services bus.

$ systemctl --user status spi.service

● spi.service - VM SPI
     Loaded: loaded (/home/polarathene/.config/systemd/user/spi.service; enabled; preset: enabled)
     Active: active (running) since Wed 2023-06-07 18:34:52 NZST; 2h 11min ago
       Docs: man:systemd-xdg-autostart-generator(8)
   Main PID: 935 (at-spi2-registr)
      Tasks: 1 (limit: 4624)
     Memory: 1.2M
        CPU: 1.123s
     CGroup: /user.slice/user-1000.slice/user@1000.service/app.slice/spi.service
             └─935 /usr/lib/at-spi2-registryd --use-gnome-session

Jun 07 18:34:52 polarathene systemd[603]: Starting VM SPI...
Jun 07 18:34:52 polarathene systemd[603]: Started VM SPI.
Jun 07 18:34:52 polarathene at-spi2-registryd[935]: SpiRegistry daemon is running with well-known name - org.a11y.atspi.Registry

~/.config/systemd/user/spi.service:

[Unit]
Description=VM SPI
# Start this unit after this dependency is started (normally invoked via DBus by vmware-user.service command):
After=at-spi-dbus-bus.service
Wants=at-spi-dbus-bus.service

[Service]
Type=exec
ExitType=cgroup
TimeoutSec=5s
# This process is now started earlier than vmware-user.service invoking it via DBus:
ExecStart=/usr/lib/at-spi2-registryd --use-gnome-session

Whereas the vmware-user.service modification just includes this additional custom service dependency:

After=graphical-session.target spi.service
Wants=spi.service

This more explicit start order for the AT-SPI bus / registryd processes appears to reliably avoid the race condition by starting them in advance, instead of via DBus.


Additional observations

Notes (Click to expand)

However I have masked the at-spi-dbus-bus.service without the above changes to prevent it from being started via DBus, and the VMware service was still flakey at being recognized as "Started".

Simply giving the VMware unit a long enough delay before it runs it's ExecStart= command (eg: ExecStartPre=sleep 10) reliably succeeds in the unit being recognized as "Started" (avoiding termination by timeout).

Same when the After=graphical-session.target is changed to Before=graphical-session.target (requires swapping the generated unit for an explicit one, since you can't unset After= via override), which reliably ensures failure of the service being considered "Started" (but otherwise functional until timeout).

Thanks to this log:

vmtoolsd[947]: gtk_disable_setlocale() must be called before gtk_init()

And knowing that the AT-SPI processes are started related to this (bus is logged prior, while registryd logged after), and that the service is only ever recognized as "Started" before this gtk_init() and AT-SPI logs appear, we have a better idea of where the race may be happening.

Still... regardless of this systemd "Started" log, the functionality will work until terminated (I've only verified copy/paste), and only appears to be an issue with Type=exec + ExitType=cgroup. It's clearly sensitive when vmtoolsd -n vmuser --blockFd 3 is run, but maybe the fault here is unrelated to what VMware processes are trying to do internally? 🤷


open-vm-tools potential sources related to early failure trigger

It's likely interaction with the system via X11-specific or RPC-specific logic is unsuccessful if initializing vmusr too early?

The RPC referenced snippets below are particularly interesting for the racey behaviour that is more common under load (but the 5 seconds error threshold should be plenty based on log timestamps?).

References (Click to expand)

Here is some open-vm-tools code that may be related to the timing behaviour?:

if (!TOOLS_IS_USER_SERVICE(ctx)) {
VMTOOLSAPP_ERROR(ctx, EXIT_FAILURE);
return FALSE;
}
/*
* We depend on the window title when performing (primitive) vmware-user
* session detection, and unfortunately for us, GTK has a nasty habit of
* retitling toplevel windows. That said, we can control GTK's default
* title by setting Glib's application or program name.
*
* XXX Consider using g_set_application_name("VMware User Agent") or
* similar.
*/
g_set_prgname(VMUSER_TITLE);
argv[0] = VMUSER_TITLE;

Then a little later in that file, the service should have been recognized as "Started" before reaching here:

/* XXX: is calling gtk_init() multiple times safe? */
gtk_init(&argc, (char ***) &argv);
if (!AcquireDisplayLock()) {
g_warning("Another instance of vmware-user already running. Exiting.\n");
VMTOOLSAPP_ERROR(ctx, EXIT_FAILURE);
return FALSE;
}

I noticed this reference to the XDG autostart service:

* Tell the session manager a little bit about ourself.
*
* The most important property to us is SmRestartStyleHint, where we hint to
* the session manager that it shouldn't attempt to restore the vmusr container
* as part of a session. (Instead, that job is handled by our XDG autostart
* entry.)

or maybe this is a likely failure trigger?:

* So, right now, let's stick with just stopping the RPC channel so that
* the host is notified the application is gone. This may cause temporary
* issues with clients that only look at capabilities and not at the
* status of vmusr.
*/
if (gCtx->rpc != NULL) {
RpcChannel_Stop(gCtx->rpc);
}
exit(EXIT_FAILURE);
} else {
/*
* _exit is used here so that any atexit() registered routines don't
* interfere with any resources shared with the parent.
*/
g_debug("%s hit from forked() child", __func__);
_exit(EXIT_FAILURE);

/* For the *nix user service app. */
if (TOOLS_IS_USER_SERVICE(state)) {
failureCb = ToolsCoreAppChannelFail;
errorLimit = ToolsCore_GetVmusrLimit(state);
}

/*
* The default number of vmusr channel errors before quitting the vmusr
* process start-up.
*/
#define VMUSR_CHANNEL_ERR_DEFAULT 5 /* approximately 5 secs. */

Potentially relevant/helpful commit messages for context:

gtk_init()

`gtk_init()` notes (seems unlikely as cause?)

For a separate PR I wanted to look into resolving this log entry:

vmtoolsd[947]: gtk_disable_setlocale() must be called before gtk_init()

GTK docs gtk_disable_setlocale():

Prevents gtk_init(), gtk_init_check(), gtk_init_with_args() and gtk_parse_args() from automatically calling setlocale(LC_ALL, "").
You would want to use this function if you wanted to set the locale for your program to something other than the user’s locale, or if you wanted to set different values for different locale categories.

Most programs should not need to call this function.

Seems the warning is a non-issue, just noise in the log that is a bit misleading.

EDIT: Actually, a grep for locale shows quite a bit of explicit handling by open-vm-tools codebase, including setting setlocale(LC_ALL, "") itself. Here's an example for vmtoolsd:

`gtk_init()` (potential to terminate if failing to initialize windowing system)

GTK docs gtk_init():

Call this function before using any other GTK+ functions in your GUI applications. It will initialize everything needed to operate the toolkit and parses some standard command line options.

This function will terminate your program if it was unable to initialize the windowing system for some reason. If you want your program to fall back to a textual interface you want to call gtk_init_check() instead.

SIGPIPE (irrelevant)

Since 2.18, GTK+ calls signal (SIGPIPE, SIG_IGN) during initialization, to ignore SIGPIPE signals, since these are almost never wanted in graphical applications.
If you do need to handle SIGPIPE for some reason, reset the handler after gtk_init(), but notice that other libraries (e.g. libdbus or gvfs) might do similar things.

Internally SIGPIPE is ignored explicitly (GTK+ 2.18 was released Sep 2009):

/* Ignore SIGUSR2 by default. */
signal(SIGUSR2, SIG_IGN);
signal(SIGPIPE, SIG_IGN);

/*
******************************************************************************
* VGAuthIgnoreSigPipe -- */ /**
*
* Ignore the SIGPIPE
*
******************************************************************************
*/
static void
VGAuthIgnoreSigPipe(void)
{
static gboolean alreadySetup = FALSE;
if (alreadySetup) {
return;
}
signal(SIGPIPE, SIG_IGN);
alreadySetup = TRUE;
}

Alternative GTK initializating via `g_option_context_parse()` (doesn't seem relevant)

Note that there are some alternative ways to initialize GTK+: if you are calling gtk_parse_args(), gtk_init_check(), gtk_init_with_args() or g_option_context_parse() with the option group returned by gtk_get_option_group(), you don’t have to call gtk_init().

g_option_context_parse() is used in a few files, for vmtoolsd we have these snippets:

/*
* ToolsCore_ParseCommandLine() uses g_option_context_parse(), which modifies
* argv. We don't want that to happen, so we make a copy of the array and
* use that as the argument instead.
*/
argvCopy = g_malloc(argc * sizeof *argvCopy);
for (i = 0; i < argc; i++) {
argvCopy[i] = argv[i];
}
setlocale(LC_ALL, "");

/*
* Form the commandline for debug log before calling
* g_option_context_parse(), because it modifies argv.
*/
cmdStr = Str_SafeAsprintf(NULL, "%s", argv[0]);
for (i = 1; i < argc; i++) {
char *prefix = cmdStr;
cmdStr = Str_SafeAsprintf(NULL, "%s %s", prefix, argv[i]);
free(prefix);
/*
* NOTE: We can't log the cmdStr here, we can
* only log it after logging gets configured.
* Logging it before ToolsCore_ReloadConfig call
* will not generate proper logs.
*/
}
context = g_option_context_new(NULL);
g_option_context_set_summary(context, N_("Runs the VMware Tools daemon."));
g_option_context_add_main_entries(context, clOptions, NULL);
g_option_group_set_error_hook(g_option_context_get_main_group(context),
ToolsCoreCmdLineError);
if (!g_option_context_parse(context, &argc, &argv, &error)) {
g_printerr("%s: %s\n", N_("Command line parsing failed"), error->message);
goto exit;
}

May overlap somewhat with concern expressed in the X11Lock file regarding calling gtk_init() multiple times?:

/* XXX: is calling gtk_init() multiple times safe? */
gtk_init(&argc, (char ***) &argv);

However I don't see usage of gtk_get_option_group(), which seems relevant for g_option_context_parse() to not require gtk_init()? Thus probably not relevant..

`gtk_init_check()` (doesn't seem relevant)

GTK docs gtk_init_check():

This function does the same work as gtk_init() with only a single change: It does not terminate the program if the commandline arguments couldn’t be parsed or the windowing system can’t be initialized. Instead it returns FALSE on failure.

This way the application can fall back to some other means of communication with the user - for example a curses or command line interface.

Note that calling any GTK function or instantiating any GTK type after this function returns FALSE results in undefined behavior.

Since it appears that the windowing system is fairly important, gtk_init_check() probably cannot substitute gtk_init().

The behaviour to terminate may be relevant 🤷‍♂️ (but I assume that'd kill the child process which seems to remain running, so perhaps not 😅 )

@polarathene
Copy link
Author

polarathene commented Jun 9, 2023

Since all of the above is incredibly verbose and quite a bit speculation of the actual cause...

TL;DR

  • A version of systemd after v253 will avoid this problem. (UPDATE: Should be v254, and this proper fix for the race condition)
  • Affected guests with installs/updates prior (roughly between 2022Q1 to 2023Q3?) can workaround the problem with a drop-in override.

Bit more info (Click to expand)

My recent upstream systemd report has effectively made this PR redundant. It may not be worth the time required to identify the actual cause in systemd or open-vm-tools as a result.

However IMO, an explicit systemd service is preferable to generating one from vmware-user.desktop. Doing so would simplify support for guests using systemd-xdg-autostart-generator without the upstream fix.

Summary

  • systemd generates a service from the XDG autostart .desktop file, but is prone to starting this too soon that it's configuration may fail to consider vmware-user-suid-wrapper as "Started" successfully (which is required for the default TimeoutSec=5s to not terminate the child process vmtoolsd -n vmusr --blockFd 3).
  • The race condition seems fairly sensitive to timing. Failure occurs at a higher rate when the host is under heavy CPU load. It can reliably fail by ensuring vmware-user-suid-wrapper unit runs Before=graphical-session.target instead of After=graphical-session.target, but only with the Type=exec + ExitType=cgroup service configuration.
  • There is a variety of workarounds:
    • Unset the timeout TimeoutSec=
    • Override Type=exec to Type=forking, or ExitType=cgroup to ExitType=main.
    • Delay running vmware-user-suid-wrapper via ExecStartPre=sleep 10 to avoid the racey behaviour issue (race only seems to be relevant to detection of the service being "Started" successfully, does not appear to affect the executed parent or child processes).

Workarounds will not be necessary for guests with a future version of systemd.

The issue with the service not being recognized as "Started" will exist, but the timeout termination will be prevented as TimeoutSec=5s has been changed to TimeoutStopSec=5s (only terminate via timeout when stopping the service).

@polarathene
Copy link
Author

polarathene commented Jun 19, 2023

Wrapping up investigating this issue.

The prior TLDR comment remains relevant, this comment just provides a little bit more information about observations of where the actual issue might be occurring.


Notes (Click to expand)

I've masked the vmware-vmblock-fuse.service (which is needed for DnD, but not copy/paste) based on this comment:

* main --
*
* On platforms where this wrapper manages the vmblock module:
* Unmounts vmblock and unloads the module, then reloads the module,
* and remounts the file system, then starts vmware-user as described
* below.
*
* This program is the only point at which vmblock is stopped or
* started. This means we must always unload the module to ensure that
* we are using the newest installed version (since an upgrade could
* have occurred since the last time this program ran).
*
* On all platforms:
* Acquires the vmblock control file descriptor, drops privileges, then
* starts vmware-user.
*
* Results:
* EXIT_SUCCESS on success and EXIT_FAILURE on failure.

But this doesn't seem to affect when the service is recognized as "Started", only logging an error that prevents an arg being appended to the vmtoolsd child process that is run:

$ systemctl --user status vmware-user

● vmware-user.service - VMware User Agent
     Loaded: loaded (/etc/xdg/autostart/vmware-user.desktop; enabled; preset: enabled)
     Active: active (running) since Fri 2023-06-09 18:56:27 NZST; 14min ago
       Docs: man:systemd-xdg-autostart-generator(8)
    Process: 690 ExecStart=/usr/bin/vmware-user-suid-wrapper (code=exited, status=0/SUCCESS)
   Main PID: 690 (code=exited, status=0/SUCCESS)
      Tasks: 4 (limit: 4624)
     Memory: 38.8M
        CPU: 1.769s
     CGroup: /user.slice/user-1000.slice/user@1000.service/app.slice/vmware-user.service
             └─693 /usr/bin/vmtoolsd -n vmusr

Jun 09 18:56:27 polarathene systemd[569]: Starting VMware User Agent...
Jun 09 18:56:27 polarathene systemd[569]: Started VMware User Agent.
Jun 09 18:56:27 polarathene vmware-user-suid-wrapper[693]: vmware-user: could not open /proc/fs/vmblock/dev
Jun 09 18:56:27 polarathene vmtoolsd[693]: gtk_disable_setlocale() must be called before gtk_init()

NOTE: The vmtoolsd process log line now sometimes names the process as vmware-user-sui (vmware-user-suid-wrapper) instead. Possibly related to being started without --blockFd 3 due to the vmblock error. This happens regardless of the unit starting successfully or not, and seems to favor the vmware-user-sui name with higher vCPU or later starting of the service.


The service is recognized as "Started" before the error "could not open /proc/fs/vmblock/dev" is logged, which might indicate the failure scenario is occurring prior?

/*
* Since vmware-user provides features that don't depend on vmblock, we
* invoke vmware-user even if we couldn't obtain a file descriptor or we
* can't parse the descriptor to pass as an argument. We set up the
* argument vector accordingly.
*/
argv[idx++] = path;
argv[idx++] = "-n";
argv[idx++] = "vmusr";
if (blockFd < 0) {
Error("could not open %s\n", VMBLOCK_DEVICE);
} else {
ret = snprintf(blockFdStr, sizeof blockFdStr, "%d", blockFd);
if (ret == 0 || ret >= sizeof blockFdStr) {
Error("could not parse file descriptor (%d)\n", blockFd);
} else {
argv[idx++] = "--blockFd";
argv[idx++] = blockFdStr;
}
}

/*
* We know the file system is mounted and want to keep this suid
* root wrapper as small as possible, so here we directly open(2) the
* "device" instead of calling DnD_InitializeBlocking() and bringing along
* a whole host of libs.
*/
blockFd = open(VMBLOCK_FUSE_DEVICE, VMBLOCK_FUSE_DEVICE_MODE);
if (blockFd < 0) {
blockFd = open(VMBLOCK_DEVICE, VMBLOCK_DEVICE_MODE);
}

According to systemd docs for Type=exec, "Started" is considered reached when fork() and execve() has completed, yet that seems to come later?:

the service manager will consider the unit started immediately after the main service binary has been executed.
exec will not proceed before both fork() and execve() in the service process succeeded

argv[idx++] = NULL;
CompatExec(path, argv, envp);
/*
* CompatExec, if successful, doesn't return. I.e., we're here only
* if CompatExec fails.
*/
Error("could not execute %s: %s\n", path, strerror(errno));
_exit(EXIT_FAILURE);

/*
*----------------------------------------------------------------------------
*
* CompatExec --
*
* Simple platform-dependent execve() wrapper.
*
* Results:
* False.
*
* Side effects:
* This function may not return.
*
*----------------------------------------------------------------------------
*/
Bool
CompatExec(const char *path, // IN: path to executable
char * const argv[], // IN: argument vector (see execve)
char * const envp[]) // IN: environment vector (see execve)
{
execve(path, argv, envp);
return FALSE;
}


Perhaps failure happens earlier, but Error() calls being logged might suggest that the only place this failure is happening is here?:

/*
*-----------------------------------------------------------------------------
*
* MaskSignals --
*
* Sets SIG_IGN as the handler for SIGUSR1 and SIGUSR2 which may arrive
* prematurely from our services script. See bug 542135.
*
* Results:
* Returns if applicable signals are blocked.
* Exits with EXIT_FAILURE otherwise.
*
* Side effects:
* SIG_IGN disposition persists across execve(). These signals will
* remain masked until vmware-user defines its own handlers.
*
*-----------------------------------------------------------------------------
*/
static void
MaskSignals(void)
{
int const signals[] = {
SIGUSR1,
SIGUSR2
};
struct sigaction olds[ARRAYSIZE(signals)];
if (Signal_SetGroupHandler(signals, olds, ARRAYSIZE(signals),
SIG_IGN) == 0) {
/* Signal_SetGroupHandler will write error message to stderr. */
exit(EXIT_FAILURE);
}
}

@polarathene
Copy link
Author

polarathene commented Jun 19, 2023

Had a look at Gnome 44.2 on the same EndeavourOS host and guest (new install for Gnome):

VMware Workstation 17 Player - 17.0.2 build-21581411

Plasma: 5.27.5
Frameworks: 5.107.0
Qt: 5.15.10

GNOME: 44.2

Kernel: 6.3.8
xorg: 21.1.8, xwayland: 23.1.2, mesa 23.1.2, vmwgfx 2.20.0
open-vm-tools: 12.2.5
systemd: 253.5

Main curiosity for checking with gnome was due to it's better copy/paste support on Wayland. None of the findings appear relevant to that improved integration however.


Notes (Click to expand)

Gnome presently does not seem to use systemd-xdg-autostart-generator, I removed the .desktop file and re-created the service in systemd explicitly (as detailed in "Earlier Investigation"). When changing After=graphical-session.target to Before=graphical-session.target it failed but differently:

○ app-vmware-user.service - VMware User Agent
     Loaded: loaded (/etc/xdg/autostart/vmware-user.desktop; enabled; preset: enabled)
     Active: inactive (dead) since Mon 2023-06-19 17:48:45 NZST; 5min ago
       Docs: man:systemd-xdg-autostart-generator(8)
    Process: 476 ExecStart=/usr/bin/vmware-user-suid-wrapper (code=exited, status=0/SUCCESS)
   Main PID: 476 (code=exited, status=0/SUCCESS)
        CPU: 113ms

Jun 19 17:48:45 polarathene systemd[425]: Starting VMware User Agent...
Jun 19 17:48:45 polarathene vmtoolsd[478]: cannot open display: 
Jun 19 17:48:45 polarathene systemd[425]: Started VMware User Agent.

This error is easy to get if running vmware-user-suid-wrapper with env option to remove the environment, as it needs DISPLAY and some other ENV available to be successful there. This service started moments earlier than gnome-shell did (which took 2 more seconds to complete). One could probably better rely on After=gnome-session.target (/usr/lib/systemd/user/gnome-session.target_) which also has a Before=graphical-session.target condition. Seems to work as a reliable failure condition.

@polarathene
Copy link
Author

@jonathanvmw what would you like to do with this PR?

  • I have raised this issue to cite benefits of maintaining a systemd service for open-vm-tools within the repo.
  • Presently distros ship their own, while this PR is about one that you'll only find some implicitly generate when systemd handles XDG autostart (may become more common in future), where the PR configures to opt-out of XDG autostart generation by providing an explicit systemd user service instead.
  • The issue this PR resolves with that systemd XDG service generator has been resolved upstream. Once distros (guests) have systemd v254 they'll no longer be affected. If the guest is unable to upgrade to that dependency, then they would only benefit from this PR if they were still able to update open-vm-tools (or the distro backported), otherwise the user must manually patch it per affected VM guest.
  • Going forward it would still seem better to use an explicit service for systemd instead of relying on XDG autostart (which seems to be unmaintained within open-vm-tools for some time). Especially since systemd is used in the majority of Linux distros.

If you'd rather take no action, I don't mind closing this if you don't see any benefit to open-vm-tools maintenance or it's affected users.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

vmware-user-suid-wrapper.desktop is not autostarted in fedora kde 35
2 participants