polkit 123-1 Failed with result 'timeout'. #207

Closed vmihalko closed 9 months ago

In GitLab by @rgudwin on Aug 17, 2023, 19:32

Current behaviour, description of the problem

After the upgrade from version 122-1 to 123-1, polkit.service is failing while starting, and the reason is: Failed with result 'timeout'.

Desired behaviour

It should start normally

Reproducer

sudo systemctl start polkit

It also happens just after reboot

Detailed description

I am running Manjaro Linux with the latest upgrades. I just upgraded polkit from version 122-1 to 123-1. Version 122-1 was running perfectly well. After the upgrade polkit fails to initialize, and many collateral effects start to appear, due to polkit not working. Doing the downgrade back to version 122-1 normalizes everything, but if I try to upgrade again, the same timeout problem reappears. Running version 122-1, I get:

systemctl status polkit
● polkit.service - Authorization Manager
     Loaded: loaded (/usr/lib/systemd/system/polkit.service; static)
     Active: active (running) since Tue 2023-08-15 19:56:05 -03; 1 day 16h ago
       Docs: man:polkit(8)
   Main PID: 749 (polkitd)
      Tasks: 4 (limit: 19144)
     Memory: 8.1M
        CPU: 1min 23.794s
     CGroup: /system.slice/polkit.service
             └─749 /usr/lib/polkit-1/polkitd --no-debug

ago 15 19:56:05 almada polkitd[749]: Started polkitd version 122
ago 15 19:56:05 almada systemd[1]: Started Authorization Manager.
ago 15 19:56:05 almada polkitd[749]: Loading rules from directory /etc/polkit-1/rules.d
ago 15 19:56:05 almada polkitd[749]: Loading rules from directory /usr/share/polkit-1/rules.d
ago 15 19:56:05 almada polkitd[749]: Finished loading, compiling and executing 10 rules
ago 15 19:56:05 almada polkitd[749]: Acquired the name org.freedesktop.PolicyKit1 on the system bus
ago 15 19:56:53 almada polkitd[749]: Registered Authentication Agent for unix-session:2 (system bus name :1.42 [/usr/lib/polkit-kde-authentication-agent-1], object path>
ago 17 11:33:34 almada polkitd[749]: Operator of unix-session:2 successfully authenticated as unix-user:admin to gain TEMPORARY authorization for action org.manjaro.p>
ago 17 11:56:41 almada polkitd[749]: Registered Authentication Agent for unix-process:552004:14404237 (system bus name :1.239974 [pkttyagent], object path /org/freedesk>
ago 17 11:57:01 almada polkitd[749]: Operator of unix-process:552004:14404237 successfully authenticated as unix-user:admin to gain TEMPORARY authorization for action>
lines 1-21/21 (END)

After I upgrade to version 123-1, I get:

systemctl status polkit.service
× polkit.service - Authorization Manager
     Loaded: loaded (/usr/lib/systemd/system/polkit.service; static)
     Active: failed (Result: timeout) since Thu 2023-08-17 13:43:12 -03; 59s ago
   Duration: 1d 17h 44min 57.038s
       Docs: man:polkit(8)
    Process: 593376 ExecStart=/usr/lib/polkit-1/polkitd --no-debug (code=killed, signal=TERM)
   Main PID: 593376 (code=killed, signal=TERM)
        CPU: 2ms

ago 17 13:41:03 almada systemd[1]: Starting Authorization Manager...
ago 17 13:42:33 almada systemd[1]: polkit.service: start operation timed out. Terminating.
ago 17 13:43:12 almada systemd[1]: polkit.service: Failed with result 'timeout'.
ago 17 13:43:12 almada systemd[1]: Failed to start Authorization Manager.

I then downgraded back to 122-1, using:

sudo pacman -U file://var/cache/pacman/pkg/polkit-122-1-x86_64.pkg.tar.zst

After the downgrade, things are back to normal, so the problem seems to be really with version 123-1. Is there any test I can do to help fixing the problem ?

In GitLab by @jrybar on Aug 23, 2023, 15:10

Hello,
just tried on fresh VM of Manjaro Gnome, upgraded polkit to 123 and everything works as expected.
Do you use SELinux? Does getenforce return Enforcing? The latest version of polkit contains unit hardening that requires changes in selinux-policy, namely allowing execution of polkit-pkla-authority with nnp_transition rule. This issue doesn't show up in journal because of a "bug" introduced lately in systemd-journald.
IOW try disabling selinux if present to determine this is the issue. Then this should be reported to SElinux maintainers in Manjaro.

In GitLab by @rgudwin on Aug 24, 2023, 15:19

I don't use SELinux. But I detected something strange ... I have a second machine, also with Manjaro KDE, and also without SELinux (both use Manjaro KDE), and the problem didn't happen on this second machine. This makes me consider that the problem might be related either to some difference in hardware, or a difference in the packages I have installed. Do you have a clue on where to start looking for ? Are you aware on what were the major changes from versions 122 to 123 ?

In GitLab by @jrybar on Aug 24, 2023, 15:48

The main changes were the unit hardening, starting polkit as a polkitd user (not root) right away and changing file/directory ownership of polkit configuration files (from root to polkitd) in order to increase security. ~~Do you have polkit-pkla-compat installed? Is it installed back again when dowgrading to 122?~~
I'm really puzzled here. Too little data. I even run polkit-123 on my own personal laptop with Manjaro Gnome and haven't noticed any issue.
Maybe I'd check the polkitd user is created correctly in /etc/passwd. Then I'd try #systemctl reload-daemon and restart the polkit service again.

In GitLab by @rgudwin on Aug 24, 2023, 16:52

This is what I have installed here, regarding polkit:

lib32-polkit 123-1
polkit 123-1
polkit-gnome 0.105-10
polkit-kde-agent 5.27.7-1 (plasma)
polkit-qt5 0.114.0-1

I have checked the polkitd user in /etc/passwd and it is the same on both my computers. Maybe the problem is running polkit as the polkitd user ... maybe it is trying to access some file owned currently by root, and this is the reason it is timing out (no authorization to read some file or folder). What are the files and paths it needs access to during initialization?

In GitLab by @jrybar on Aug 24, 2023, 16:59

Hmm, if polkit had no access to the files, it would definitely pass messages about it into journal, hence it would show up in report from systemctl status, e.g. "error while loading rules files" etc. The ownership should have no effect because before 123 polkit started as root and immediately switched to polkitd before even loading the configuration files. Can you post the whole journal from unit start to its killing (or from last boot)?

In GitLab by @rgudwin on Aug 24, 2023, 17:16

This is what I get from journalctl:

ago 24 12:04:32 almada systemd[1]: Stopped Authorization Manager.
░░ Subject: A stop job for unit polkit.service has finished
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A stop job for unit polkit.service has finished.
░░ 
░░ The job identifier is 41760 and the job result is done.
ago 24 12:04:32 almada systemd[1]: Starting Authorization Manager...
░░ Subject: A start job for unit polkit.service has begun execution
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A start job for unit polkit.service has begun execution.
░░ 
░░ The job identifier is 41760.
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.151320:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.151853:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.152430:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.152976:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.153505:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.154019:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.154547:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.155106:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.155731:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.156255:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.156809:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.157397:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.157935:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.158491:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.159091:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.159598:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.160176:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)

... many lines like this (more than 2000)

ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.599358:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.599617:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.599951:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.600174:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.600462:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.600724:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.600974:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.601247:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.601489:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.601859:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.602094:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.602344:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.602596:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.602860:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.603118:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.603379:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.603654:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.603918:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.604173:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.604420:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.604701:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.604971:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.605304:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.605564:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.605847:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.606064:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.606311:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.606563:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.606827:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.607114:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.607363:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.607620:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.607893:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.608138:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.608482:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.608772:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.609001:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.609258:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.609515:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.609772:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.610060:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.610306:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.610567:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.610833:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:05:03 almada ksmserver[1616]: [1611:1611:0824/120503.611089:ERROR:CONSOLE(6)] "console.assert", source: devtools://devtools/bundled/panels/console/console.js (6)
ago 24 12:06:03 almada systemd[1]: polkit.service: start operation timed out. Terminating.
ago 24 12:06:42 almada systemd[1]: polkit.service: Failed with result 'timeout'.
░░ Subject: Unit failed
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ The unit polkit.service has entered the 'failed' state with result 'timeout'.
ago 24 12:06:42 almada systemd[1]: Failed to start Authorization Manager.
░░ Subject: A start job for unit polkit.service has failed
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A start job for unit polkit.service has finished with a failure.
░░ 
░░ The job identifier is 41760 and the job result is failed.
ago 24 12:06:42 almada sudo[2850473]: pam_unix(sudo:session): session closed for user root

Apparentlly there is something related to ksmserver, which is the responsible for the timeout. Any hint ?

In GitLab by @jrybar on Aug 24, 2023, 17:38

Hmm, the "console.assert" message is said to be related to Electron. Did you do full system upgrade? Do you have the correct JS backend installed (duktape by default)? Do you use your own build with mozjs selected as polkit JS backend?

I just installed a fresh Manjaro KDE VM and no problem there (except it needs glibc-2.38 explicitly updated).

In GitLab by @rgudwin on Aug 24, 2023, 23:02

Apparently Electron is really the one to culprit. I indeed have Electron installed in the machine where the problem happens, and don't have it installed on the machine where it worked. Nevertheless, I uninstalled Electron, and unfortunately the problem keeps happening, It seems the uninstallation of Electron is not gentle enough to uninstall everything ... and this console.assert is still disturbing the correct initialization of polkit. Do you know how I can manually get rid of this ? Or why this is causing polkit to fail initialization ?

In GitLab by @rgudwin on Aug 24, 2023, 23:31

Maybe it is an electron dependency,that was installed together with electron, but was not removed when I removed electron ? Nevertheless ... do you believe you can install electron there and test if the problems appears to you too ?

In GitLab by @rgudwin on Aug 25, 2023, 01:18

Hmmm ... maybe electron has nothing to do with it ... apparently those lines were due to my browser being opened while I was trying to do the sudo systemctl restart polkit. I closed the browser and everything else, and the timeout is still happening, but now without the message on console.assert. This is the journalctl:

ago 24 19:32:22 almada dbus-daemon[782]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.2284' (uid=0 pid=8703 comm="sudo pacman -Su polkit")
ago 24 19:32:22 almada dbus-daemon[782]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
ago 24 19:32:27 almada sudo[8703]:  admin : TTY=pts/3 ; PWD=/ ; USER=root ; COMMAND=/usr/bin/pacman -Su polkit
ago 24 19:32:27 almada sudo[8703]: pam_unix(sudo:session): session opened for user root(uid=0) by admin(uid=1000)
ago 24 19:32:31 almada polkitd[7936]: Reloading rules
ago 24 19:32:31 almada polkitd[7936]: Collecting garbage unconditionally...
ago 24 19:32:31 almada polkitd[7936]: Loading rules from directory /etc/polkit-1/rules.d
ago 24 19:32:31 almada polkitd[7936]: Loading rules from directory /usr/share/polkit-1/rules.d
ago 24 19:32:31 almada polkitd[7936]: Finished loading, compiling and executing 9 rules
ago 24 19:32:31 almada dbus-daemon[782]: [system] Reloaded configuration
ago 24 19:32:31 almada dbus-daemon[782]: [system] Reloaded configuration
ago 24 19:32:31 almada dbus-daemon[782]: [system] Reloaded configuration
ago 24 19:32:31 almada systemd[1]: Reloading requested from client PID 8779 (unit user@1000.service)...
ago 24 19:32:31 almada systemd[1]: Reloading...
ago 24 19:32:31 almada polkitd[7936]: Reloading rules
ago 24 19:32:31 almada polkitd[7936]: Collecting garbage unconditionally...
ago 24 19:32:31 almada polkitd[7936]: Loading rules from directory /etc/polkit-1/rules.d
ago 24 19:32:31 almada polkitd[7936]: Loading rules from directory /usr/share/polkit-1/rules.d
ago 24 19:32:31 almada polkitd[7936]: Finished loading, compiling and executing 10 rules
ago 24 19:32:31 almada polkitd[7936]: Reloading rules
ago 24 19:32:31 almada polkitd[7936]: Collecting garbage unconditionally...
ago 24 19:32:31 almada polkitd[7936]: Loading rules from directory /etc/polkit-1/rules.d
ago 24 19:32:31 almada polkitd[7936]: Loading rules from directory /usr/share/polkit-1/rules.d
ago 24 19:32:31 almada polkitd[7936]: Finished loading, compiling and executing 10 rules
ago 24 19:32:31 almada systemd[1]: Reloading finished in 493 ms.
ago 24 19:32:32 almada systemd[1]: Reloading D-Bus System Message Bus...
░░ Subject: A reload job for unit dbus.service has begun execution
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A reload job for unit dbus.service has begun execution.
░░ 
░░ The job identifier is 4167.
ago 24 19:32:32 almada dbus-daemon[782]: [system] Reloaded configuration
ago 24 19:32:32 almada dbus-send[8827]: method return time=1692916352.189295 sender=org.freedesktop.DBus -> destination=:1.2300 serial=3 reply_serial=2
ago 24 19:32:32 almada systemd[1]: Reloaded D-Bus System Message Bus.
░░ Subject: A reload job for unit dbus.service has finished
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A reload job for unit dbus.service has finished.
░░ 
░░ The job identifier is 4167 and the job result is done.
ago 24 19:32:32 almada sudo[8703]: pam_unix(sudo:session): session closed for user root
ago 24 19:32:36 almada pamac-tray-plas[1370]: updates_checker.vala:71: check updates
ago 24 19:32:38 almada pamac-tray-plas[1370]: updates_checker.vala:101: 0 updates found
ago 24 19:33:00 almada dbus-daemon[782]: [system] Activating via systemd: service name='org.freedesktop.home1' unit='dbus-org.freedesktop.home1.service' requested by ':1.2346' (uid=0 pid=8942 comm="sudo systemctl restart polkit")
ago 24 19:33:00 almada dbus-daemon[782]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.
ago 24 19:33:00 almada sudo[8942]:  admin : TTY=pts/3 ; PWD=/ ; USER=root ; COMMAND=/usr/bin/systemctl restart polkit
ago 24 19:33:00 almada sudo[8942]: pam_unix(sudo:session): session opened for user root(uid=0) by admin(uid=1000)
ago 24 19:33:00 almada systemd[1]: Stopping Authorization Manager...
░░ Subject: A stop job for unit polkit.service has begun execution
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A stop job for unit polkit.service has begun execution.
░░ 
░░ The job identifier is 4168.
ago 24 19:33:00 almada systemd[1]: polkit.service: Deactivated successfully.
░░ Subject: Unit succeeded
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ The unit polkit.service has successfully entered the 'dead' state.
ago 24 19:33:00 almada systemd[1]: Stopped Authorization Manager.
░░ Subject: A stop job for unit polkit.service has finished
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A stop job for unit polkit.service has finished.
░░ 
░░ The job identifier is 4168 and the job result is done.
ago 24 19:33:00 almada systemd[1]: Starting Authorization Manager...
░░ Subject: A start job for unit polkit.service has begun execution
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A start job for unit polkit.service has begun execution.
░░ 
░░ The job identifier is 4168.
ago 24 19:34:30 almada systemd[1]: polkit.service: start operation timed out. Terminating.
ago 24 19:35:08 almada systemd[1]: polkit.service: Failed with result 'timeout'.
░░ Subject: Unit failed
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ The unit polkit.service has entered the 'failed' state with result 'timeout'.
ago 24 19:35:08 almada systemd[1]: Failed to start Authorization Manager.
░░ Subject: A start job for unit polkit.service has failed
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A start job for unit polkit.service has finished with a failure.
░░ 
░░ The job identifier is 4168 and the job result is failed.
ago 24 19:35:08 almada sudo[8942]: pam_unix(sudo:session): session closed for user root

As you can see, apparently there is nothing after 19:33:00 when the polkit.service stopped and started again, now with failure. But it is remarkable that the first time it was initialized, just after the upgrade, it worked at 19:32:31. What I am suspecting now is that it is something related to dbus, because at the beginning of 19:33:00, after restarting dbus, I got the following message:

Activation via systemd failed for unit 'dbus-org.freedesktop.home1.service': Unit dbus-org.freedesktop.home1.service not found.

Do you believe this is something related to this home1 service that might be affecting the initialization ? Because at the first time, it worked, after restarting dbus, it is not working anymore. What do you think ?

In GitLab by @jrybar on Aug 25, 2023, 10:31

I'll do some testing with systemd-homed later today.

In GitLab by @rgudwin on Aug 25, 2023, 22:24

The point with systemd-homed probably is not the culprit. I just discovered it was not enabled. I enabled it and started it, and the message disappeared. I now have other interesting experiments. I decided to run polkitd without the --no-debug:

$ sudo /usr/lib/polkit-1/polkitd 
[sudo] password for admin: 
Successfully changed to user polkitd
17:02:00.935: Loading rules from directory /etc/polkit-1/rules.d
17:02:00.935: Loading rules from directory /usr/share/polkit-1/rules.d
17:02:00.937: Finished loading, compiling and executing 10 rules
Entering main event loop
Connected to the system bus
17:02:00.938: Acquired the name org.freedesktop.PolicyKit1 on the system bus

Apparently, it is working. The only thing is that it does not enter in background, as it was expected to do. Checking now the journalctl, I had:

ago 25 17:01:24 almada sudo[305620]: pam_unix(sudo:session): session closed for user root
ago 25 17:02:00 almada sudo[306276]:  admin : TTY=pts/4 ; PWD=/home/admin ; USER=root ; COMMAND=/usr/l>
ago 25 17:02:00 almada sudo[306276]: pam_unix(sudo:session): session opened for user root(uid=0) by admin(uid=10>
ago 25 17:02:00 almada polkitd[306300]: Started polkitd version 123
ago 25 17:02:00 almada polkitd[306300]: Loading rules from directory /etc/polkit-1/rules.d
ago 25 17:02:00 almada polkitd[306300]: Loading rules from directory /usr/share/polkit-1/rules.d
ago 25 17:02:00 almada polkitd[306300]: Finished loading, compiling and executing 10 rules
ago 25 17:02:00 almada polkitd[306300]: Acquired the name org.freedesktop.PolicyKit1 on the system bus

I then used pamac to install something ... in order to use polkit. It worked, which means polkit is fully operational. So, in resume ... apparently, there is a problem of polkit with systemd, in the sense that the daemon is not going into background, as it would be expected. Probably, this is the reason for the timeout. It is waiting for polkitd to go into background, but it never goes.
Do you have any clue on why it is not going into background ? Maybe I need to make a change in the polkit.service to run it in background ? Or something related to dbus ? Also, when I run pamac, I received:

17:12:47.237: Registered Authentication Agent for unix-process:309635:7941109 (system bus name :1.123851 [pkttyagent], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8)
17:12:55.637: Operator of unix-process:309635:7941109 successfully authenticated as unix-user:admin to gain TEMPORARY authorization for action org.manjaro.pamac.commit for system-bus-name::1.123850 [pamac install blender] (owned by unix-user:admin)
17:13:45.796: Unregistered Authentication Agent for unix-process:309635:7941109 (system bus name :1.123851, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)

I just noticed the message: (disconnected from bus) ... maybe something related to dbus ?

In GitLab by @rgudwin on Aug 25, 2023, 22:52

I did the same thing with dbus-launch and the results were the same:

$ sudo dbus-launch /usr/lib/polkit-1/polkitd 
Successfully changed to user polkitd
17:43:53.736: Loading rules from directory /etc/polkit-1/rules.d
17:43:53.736: Loading rules from directory /usr/share/polkit-1/rules.d
17:43:53.738: Finished loading, compiling and executing 10 rules
Entering main event loop
Connected to the system bus
17:43:53.739: Acquired the name org.freedesktop.PolicyKit1 on the system bus

It does not enter into background. Hmmmm ... downgraded to version 122 and it does not enter into background when run like this. But if I do a sudo systemctl start polkit, it goes into background. What am I missing here ? Maybe I don't understand properly what is happening besides systemd.

In GitLab by @rgudwin on Aug 26, 2023, 24:27

Another issue ... when I run systemctl show polkit, I noticed that:

UID=[not set]
GID=[not set]

but when I do the same in my other machine, where polkit is working, I get:

UID=102
GID=102

Is it relevant, or it is the case just because the service does not really started ?

In GitLab by @rgudwin on Aug 26, 2023, 24:46

Also, I noticed the following:

ago 25 19:37:37 almada sudo[345269]:  admin : TTY=pts/6 ; PWD=/var/log ; USER=root ; COMMAND=/usr/bin/systemctl start polkit
ago 25 19:37:37 almada sudo[345269]: pam_unix(sudo:session): session opened for user root(uid=0) by admin(uid=1000)
ago 25 19:37:37 almada systemd[1]: Starting Authorization Manager...
░░ Subject: A start job for unit polkit.service has begun execution
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░ 
░░ A start job for unit polkit.service has begun execution.
░░ 
░░ The job identifier is 23291.
ago 25 19:38:37 almada sudo[345269]: pam_unix(sudo:session): session closed for user root
ago 25 19:39:07 almada systemd[1]: polkit.service: start operation timed out. Terminating.

I am suspecting now about the line:

ago 25 19:38:37 almada sudo[345269]: pam_unix(sudo:session): session closed for user root

Apparently, a sudo was denied by pam ... maybe this is related to the UID and GID not being set ?

In GitLab by @jrybar on Aug 29, 2023, 13:00

The /usr/lib/polkit-1/polkitd binary is not supposed to be run explicitly by the user. Either systemd runs it as a daemon or, in case of systemd-less system, the other init system arranges its execution and daemonization. That's why it's still hooked to the terminal if you run the binary explicitly. (Please note that according to the Filesystem Hierarchy Standard no binary under /usr/lib is supposed to be run by the user.) ~~Please, the output of sudo journalctl -u polkit.service might help here a bit.~~

In GitLab by @jrybar on Aug 29, 2023, 13:40

That's really weird, the unit file should contain 'polkitd' by default.

Please run grep -e "User\=\|Group\=" /usr/lib/systemd/system/polkit.service to see if user/group is set correctly. If not, edit the file, fill it in and run the following and see if the problem is fixed.

$ sudo systemctl daemon-reload
$ sudo systemctl restart polkit

If User= and/or Group= are unset, we've got the root of all trouble, as systemd doesn't know under what user/group the service should be executed. This should be visible in journal though.

Please note that this behaviour is nonstandard and should not happen on an untampered system.

In GitLab by @rgudwin on Aug 29, 2023, 15:22

No, the polkit.service correctly states:

User=polkitd
Group=polkitd

Probably the systemctl show polkit shows UID and GID 'not set' because the systemctl restart polkit incurs in a timeout.

I was investigating the /etc/nsswitch.conf of both my machines, the one with the problem and the one where things are working. I noticed a difference in that the machine where things work has an extra line:

gshadow: files systemd

Do you believe this might have some effect on the odd behavior we are observing ?

In GitLab by @rgudwin on Aug 29, 2023, 15:34

Yes, I know !! It was just a wild test trying to discover what is blocking the process. Running it by hand (as root), apparently, it works, except for not going into background. The question is: why I can´t run it through systemd ? I just reinstalled systemd, just in case some of its files might be corrupted. But the strange behavior remains. So, this is not the case. I am trying to look at both my machines, both with Manjaro KDE, both with last updated software, to try to discover what is different between them, that could be the source of this problem. One possible difference is that the machine with the problem uses nis to authenticate. Do you believe this could cause some odd effect ?

In GitLab by @zbyszek on Aug 30, 2023, 10:44

Please attach the output from systmectl cat polkit

In GitLab by @rgudwin on Aug 30, 2023, 14:01

There it is:

[Unit]
Description=Authorization Manager
Documentation=man:polkit(8)

[Service]
Type=dbus
BusName=org.freedesktop.PolicyKit1
CapabilityBoundingSet=
DeviceAllow=/dev/null rw
DevicePolicy=strict
ExecStart=/usr/lib/polkit-1/polkitd --no-debug
User=polkitd
Group=polkitd
IPAddressDeny=any
LimitMEMLOCK=0
LockPersonality=yes
MemoryDenyWriteExecute=yes
NoNewPrivileges=yes
PrivateDevices=yes
PrivateNetwork=yes
PrivateTmp=yes
ProtectControlGroups=yes
ProtectHome=yes
ProtectKernelModules=yes
ProtectKernelLogs=yes
ProtectKernelTunables=yes
ProtectSystem=strict
ProtectClock=yes
ProtectHostname=yes
RemoveIPC=yes
RestrictAddressFamilies=AF_UNIX
RestrictNamespaces=yes
RestrictRealtime=yes
RestrictSUIDSGID=yes
SystemCallArchitectures=native
SystemCallFilter=@system-service

In GitLab by @zbyszek on Aug 31, 2023, 11:38

Hmmm, this is not an output from systemctl cat command… Please use systemctl cat polkit.

In GitLab by @jrybar on Aug 31, 2023, 12:29

I think it is, Zbyszek. I get the same output from systemctl cat polkit on Manjaro VM.
IMO everything LGTM, except I see a bug made by me in CapabilityBoundingSet=. Looks not associated with the issue.
Anyway, I still fail to reproduce the issue on fresh Manjaro KDE vm with polkit-123. Everything works as it should.

In GitLab by @jrybar on Aug 31, 2023, 12:32

This looks the same on fresh system. I guess it's not the cause. This makes the authentication take passwords from /etc/shadow. But please attach the whole contents of /etc/nsswitch.conf here. Maybe some other source of UIDs (LDAP or whatever) in misconfigured nsswitch causes this.

In GitLab by @jrybar on Aug 31, 2023, 12:39

@rgudwin also UMask=0077 is missing from your configuration. That's the only deviation from upstream version I see.

In GitLab by @zbyszek on Aug 31, 2023, 16:25

systemctl cat adds a header that specifies the file name. This is important, because it shows where the file was loaded from. I wanted to know if it is using the (unmodified) package file and if there are any drop-ins.

In GitLab by @rgudwin on Aug 31, 2023, 16:32

Sorry, I mistakenly cut part of the output:

# /usr/lib/systemd/system/polkit.service
[Unit]
Description=Authorization Manager
Documentation=man:polkit(8)

[Service]
Type=dbus
BusName=org.freedesktop.PolicyKit1
CapabilityBoundingSet=
DeviceAllow=/dev/null rw
DevicePolicy=strict
ExecStart=/usr/lib/polkit-1/polkitd --no-debug
User=polkitd
Group=polkitd
IPAddressDeny=any
LimitMEMLOCK=0
LockPersonality=yes
MemoryDenyWriteExecute=yes
NoNewPrivileges=yes
PrivateDevices=yes
PrivateNetwork=yes
PrivateTmp=yes
ProtectControlGroups=yes
ProtectHome=yes
ProtectKernelModules=yes
ProtectKernelLogs=yes
ProtectKernelTunables=yes
ProtectSystem=strict
ProtectClock=yes
ProtectHostname=yes
RemoveIPC=yes
RestrictAddressFamilies=AF_UNIX
RestrictNamespaces=yes
RestrictRealtime=yes
RestrictSUIDSGID=yes
SystemCallArchitectures=native
SystemCallFilter=@system-service
UMask=0077

In GitLab by @zbyszek on Aug 31, 2023, 16:33

OK, thanks. So we know that there are no drop-ins that could explain the issue. My hypothesis is disproved ;)

In GitLab by @rgudwin on Aug 31, 2023, 16:36

I added the gshadow line, just in case, but it didn't change anything. This the whole nsswitch.conf, after the insertion of the gshadow line:

# Name Service Switch configuration file.
# See nsswitch.conf(5) for details.

passwd: files mymachines systemd nis
group: files mymachines systemd nis
shadow: files systemd nis
gshadow: files systemd nis

publickey: files

hosts: files mymachines mdns4_minimal [NOTFOUND=return] resolve [!UNAVAIL=return] dns mdns4 myhostname nis
networks: files

protocols: files
services: files
ethers: files
rpc: files

netgroup: files

In GitLab by @rgudwin on Aug 31, 2023, 16:56

Does the service access any file, not provided by the package, that could have its permission different from expected?

In GitLab by @jrybar on Aug 31, 2023, 17:27

Yes, basically any .rules and .action files vendored by other packages that use polkit. But those files are accessed when loaded by polkit, which means polkit would have to be already running. Seriously, we need the entire journal output at least from the moment systemd tries to run the polkit.service. If there is a conflict with other services, this could throw some light on it. So far I feel like shooting into the dark.
sudo journalctl -S <time> where <time> is the time seconds before systemctl restart polkit is run. I believe that would help.

In GitLab by @rgudwin on Sep 4, 2023, 23:49

Do you believe there will be a possibility of running a tampered version (with logs) of polkit that might give us a clue on the reason for this timeout ? In other words, to detect where it is entering into an infinite wait for something that never comes ? I was planning to download the source code and maybe instrument it in such a way I can detect why it is blocking, but I am afraid the code is not simple enough for someone that never saw it before, right ? I am really stuck here, and would like to help, but don't know exactly how. Would you like to have access to my machine and run experiments here ? I can survive using version 122 instead of 123, but the problem is that for any new upgrade of another package I have to make further a downgrade of polkit back to 122. This really starts to be annoying. Or maybe I could try to run a pendrive bootable distribution, already with polkit 123 and see if the problem still remains (which would lead us to a hardware problem), or if it runs flawless, which would indicate a software problem.

In GitLab by @jrybar on Sep 5, 2023, 09:51

I don't think a modified version of polkit would help since it cannot even be started by systemd.
You can try to modify your polkit.service file with the following command and content, just to be sure the systemd sandboxing is not to blame (and so you can continue with the latest version of polkit), but be warned it's less safe:
sudo systemctl edit --full polkit

[Unit]
Description=Authorization Manager
Documentation=man:polkit(8)

[Service]
Type=dbus
BusName=org.freedesktop.PolicyKit1
#CapabilityBoundingSet=
#DeviceAllow=/dev/null rw
#DevicePolicy=strict
ExecStart=/usr/lib/polkit-1/polkitd --no-debug
User=polkitd
Group=polkitd
#IPAddressDeny=any
#LimitMEMLOCK=0
#LockPersonality=yes
#MemoryDenyWriteExecute=yes
#NoNewPrivileges=yes
#PrivateDevices=yes
#PrivateNetwork=yes
#PrivateTmp=yes
#ProtectControlGroups=yes
#ProtectHome=yes
#ProtectKernelModules=yes
#ProtectKernelLogs=yes
#ProtectKernelTunables=yes
#ProtectSystem=strict
#ProtectClock=yes
#ProtectHostname=yes
#RemoveIPC=yes
#RestrictAddressFamilies=AF_UNIX
#RestrictNamespaces=yes
#RestrictRealtime=yes
#RestrictSUIDSGID=yes
#SystemCallArchitectures=native
#SystemCallFilter=@system-service
#UMask=0077

In GitLab by @jrybar on Sep 5, 2023, 09:53

@rgudwin, please provide us with the journal as mentioned in https://gitlab.freedesktop.org/polkit/polkit/-/issues/203#note_2066632. Thank you.

In GitLab by @rgudwin on Sep 5, 2023, 17:37

Good news ... I detected what is causing the problem ... it is the line:

IPAddressDeny=any

If I just comment this specific line, polkit starts flawlessly, without doing the timeout ! Does this information enlighten you regarding the cause of this problem ? What is the purpose of this flag ? Do you still need the journal ? With this line commented or with the original configuration ?

In GitLab by @rgudwin on Sep 5, 2023, 18:48

Wild guess here ... one difference from the machine where the error appears and the other where it works is that the machine with problem is part of a network domain and the one where it works is my home machine. My guess is that possibly a network connection for the own machine is done using the machine IP address instead of localhost. As IPAdressDeny=any, it denies the access for everything but localhost, but the connection is not being done to localhost, but to the machine IP address instead, and as it is denied, it times out. Do you believe this can be the case ?

In GitLab by @bluca on Sep 5, 2023, 23:42

Your machine where it doesn't work probably has some severe issues that break BPF, which is used for that setting.

@jrybar I recommend to drop IPAddressDeny=. Given AFs are already restricted to AF_UNIX and a private network namespace is used, it serves no purposes and provides no advantage, and evidently makes some weird local issue with BPF surface like this as a side effect.

In GitLab by @jrybar on Sep 6, 2023, 13:35

Alright, since this doesn't look like a bug in polkit and we cannot retrieve any journal or other marks that prove otherwise, I'm closing this issue for insufficient data.
Thanks everyone involved in this bughunting.

In GitLab by @rgudwin on Sep 6, 2023, 16:37

Jan, I am not completely sure this is not a bug in polkit. It seems there is a bug in that something during initialization (it can be polkit itself) is trying to open a socket into polkit, but it is not allowing due to the IPAddressDeny=any. In situations where this socket is tried at localhost, it seems to work. When it tries to use the machine IP, it is denied, leading to the timeout. This could happen, e.g., in situations where you just define the port to connect, without specifying the IP address, and the IP address is determined automatically. Depending on the machine where polkit is installed, it might default to localhost or the machine IP. Then, it will cause a bug in timeout, if the machine is configured to use the machine IP instead of localhost as its default IP address. Is there such a situation in polkit initialization ?

In GitLab by @bluca on Sep 6, 2023, 16:41

There is no such thing. The other sandboxing options (that are working) ensure that only AF_UNIX sockets can be opened, so it's not even possible to open connect to any ip address. I am pretty sure you have some kernel/BPF issue on the machine where you tried this.

vmihalko / t2_polkit