1398000 – Something’s broken with authentication

Bug 1398000 - Something’s broken with authentication

Summary: Something’s broken with authentication

Keywords:
Status:	CLOSED WORKSFORME
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	polkit
Sub Component:
Version:	7.4
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	rc
Target Release:	---
Assignee:	Polkit Maintainers
QA Contact:	qe-baseos-daemons
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2016-11-23 19:32 UTC by Matěj Cepl
Modified:	2019-09-25 17:06 UTC (History)
CC List:	3 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2019-09-25 17:06:10 UTC
Target Upstream Version:

Attachments	(Terms of Use)
output of journalctl -xb (1.44 MB, text/plain) 2016-11-23 19:32 UTC, Matěj Cepl	no flags	Details
View All Add an attachment (proposed patch, testcase, etc.)

Description Matěj Cepl 2016-11-23 19:32:08 UTC

Created attachment 1223413 [details]
output of journalctl -xb

Description of problem:
There are many errors in journalctl -xb (see attached) and applications depending on polkit authentication seem not to work:

    Nov 23 20:21:19 mitmanek packagekitd[4323]: Error cancelling authorization check: Časový limit vypršel
    Nov 23 20:21:21 mitmanek NetworkManager[1313]: <debug> [1479928881.8888] device[0x7f119de2c010] (wlp3s0): add_pending_action (1): 'scan'
    Nov 23 20:21:21 mitmanek NetworkManager[1313]: <debug> [1479928881.8914] device[0x7f119de2c010] (wlp3s0): remove_pending_action (0): 'scan'
    Nov 23 20:21:23 mitmanek gnome-shell[5230]: JS LOG: Received error from DBus search provider org.gnome.Documents.desktop: Gio.IOErrorEnum: Timeout was reached
    Nov 23 20:21:25 mitmanek NetworkManager[1313]: <trace> [1479928885.8202] platform-linux: event-notification: NEWLINK, seq 0: 3: wlp3s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 0 arp 1 wifi? not-init addrgenmode eui64 addr E8:B1:FC:02:42:ED rx:2,282 tx:2,288
    Nov 23 20:21:25 mitmanek NetworkManager[1313]: <trace> [1479928885.8244] exported-object[0x7f119deb81b0]: unexport: "/org/freedesktop/NetworkManager/AccessPoint/608"
    Nov 23 20:21:25 mitmanek NetworkManager[1313]: <trace> [1479928885.8519] exported-object[0x7f11840024c0]: export: "/org/freedesktop/NetworkManager/AccessPoint/609"
    Nov 23 20:21:25 mitmanek NetworkManager[1313]: <trace> [1479928885.8536] exported-object[0x7f119de9ba50]: export: "/org/freedesktop/NetworkManager/AccessPoint/610"
    Nov 23 20:21:25 mitmanek NetworkManager[1313]: <trace> [1479928885.8549] exported-object[0x7f119de23750]: export: "/org/freedesktop/NetworkManager/AccessPoint/611"
    Nov 23 20:21:53 mitmanek transmission-daemon[10461]: Charlotte_Bronte.Villette.[2007].BBC_Radio_drama.ogg.radioCat Scrape error: Connection failed (announcer.c:1279)
    Nov 23 20:21:53 mitmanek transmission-daemon[10461]: Charlotte_Bronte.Villette.[2007].BBC_Radio_drama.ogg.radioCat Retrying scrape in 20 seconds. (announcer.c:1288)
    Nov 23 20:21:54 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:20: Starting /usr/bin/pkla-check-authorization matej true true org.freedesktop.timedate1.set-timezone
    Nov 23 20:21:54 mitmanek crond[32094]: (matej) INFO (Job execution of per-minute job scheduled for 20:15 delayed into subsequent minute 20:21. Skipping job run.)
    Nov 23 20:22:04 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:21: Error: Error spawning helper: Timed out after 10 seconds (g-io-error-quark, 24)
    Nov 23 20:22:04 mitmanek polkitd[1240]: Error evaluating authorization rules
    Nov 23 20:22:05 mitmanek PackageKit[4323]: resolve transaction /8586_adadeaab from uid 1000 finished with success after 805ms
    Nov 23 20:22:05 mitmanek PackageKit[4323]: new remove-packages transaction /8587_bebcddcd scheduled from uid 1000
    Nov 23 20:22:09 mitmanek PackageKit[4323]: in /8587_bebcddcd for remove-packages package imake;1.0.5-10.el7;x86_64;installed:rhel-nightly was removing for uid 1000
    Nov 23 20:22:09 mitmanek PackageKit[4323]: remove-packages transaction /8587_bebcddcd from uid 1000 finished with success after 3642ms
    Nov 23 20:22:11 mitmanek PackageKit[4323]: uid 1000 is trying to obtain org.freedesktop.packagekit.package-remove auth (only_trusted:0)
    Nov 23 20:22:52 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:20: Starting /usr/bin/pkla-check-authorization matej true true org.gnome.controlcenter.datetime.configure
    Nov 23 20:23:02 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:21: Error: Error spawning helper: Timed out after 10 seconds (g-io-error-quark, 24)
    Nov 23 20:23:02 mitmanek polkitd[1240]: Error evaluating authorization rules
    Nov 23 20:23:21 mitmanek NetworkManager[1313]: <debug> [1479929001.8884] device[0x7f119de2c010] (wlp3s0): add_pending_action (1): 'scan'
    Nov 23 20:23:21 mitmanek NetworkManager[1313]: <debug> [1479929001.8903] device[0x7f119de2c010] (wlp3s0): remove_pending_action (0): 'scan'
    Nov 23 20:23:26 mitmanek NetworkManager[1313]: <trace> [1479929006.0377] platform-linux: event-notification: NEWLINK, seq 0: 3: wlp3s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 0 arp 1 wifi? not-init addrgenmode eui64 addr E8:B1:FC:02:42:ED rx:2,282 tx:2,288
    Nov 23 20:23:26 mitmanek NetworkManager[1313]: <trace> [1479929006.0386] exported-object[0x7f119de9b9b0]: unexport: "/org/freedesktop/NetworkManager/AccessPoint/597"
    Nov 23 20:23:26 mitmanek NetworkManager[1313]: <trace> [1479929006.0393] exported-object[0x7f1184002240]: unexport: "/org/freedesktop/NetworkManager/AccessPoint/606"
    Nov 23 20:23:50 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:20: Starting /usr/bin/pkla-check-authorization matej true true org.freedesktop.timedate1.set-time
    Nov 23 20:24:00 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:21: Error: Error spawning helper: Timed out after 10 seconds (g-io-error-quark, 24)
    Nov 23 20:24:00 mitmanek polkitd[1240]: Error evaluating authorization rules
    Nov 23 20:24:48 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:20: Starting /usr/bin/pkla-check-authorization matej true true org.freedesktop.packagekit.trigger-offline-update
    Nov 23 20:24:58 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:21: Error: Error spawning helper: Timed out after 10 seconds (g-io-error-quark, 24)
    Nov 23 20:24:58 mitmanek polkitd[1240]: Error evaluating authorization rules
    Nov 23 20:25:21 mitmanek NetworkManager[1313]: <debug> [1479929121.8890] device[0x7f119de2c010] (wlp3s0): add_pending_action (1): 'scan'
    Nov 23 20:25:21 mitmanek NetworkManager[1313]: <debug> [1479929121.8908] device[0x7f119de2c010] (wlp3s0): remove_pending_action (0): 'scan'
    Nov 23 20:25:26 mitmanek NetworkManager[1313]: <trace> [1479929126.0506] platform-linux: event-notification: NEWLINK, seq 0: 3: wlp3s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 0 arp 1 wifi? not-init addrgenmode eui64 addr E8:B1:FC:02:42:ED rx:2,282 tx:2,288
    Nov 23 20:25:26 mitmanek NetworkManager[1313]: <trace> [1479929126.0518] exported-object[0x7f11840021a0]: unexport: "/org/freedesktop/NetworkManager/AccessPoint/605"
    Nov 23 20:25:26 mitmanek NetworkManager[1313]: <trace> [1479929126.0525] exported-object[0x7f11840024c0]: unexport: "/org/freedesktop/NetworkManager/AccessPoint/609"
    Nov 23 20:25:26 mitmanek NetworkManager[1313]: <trace> [1479929126.0530] exported-object[0x7f119de23430]: unexport: "/org/freedesktop/NetworkManager/AccessPoint/603"
    Nov 23 20:25:26 mitmanek NetworkManager[1313]: <trace> [1479929126.0536] exported-object[0x7f119de9ba50]: unexport: "/org/freedesktop/NetworkManager/AccessPoint/610"
    Nov 23 20:25:26 mitmanek NetworkManager[1313]: <trace> [1479929126.0655] exported-object[0x7f11840024c0]: export: "/org/freedesktop/NetworkManager/AccessPoint/612"
    Nov 23 20:25:26 mitmanek NetworkManager[1313]: <trace> [1479929126.0661] exported-object[0x7f11840021a0]: export: "/org/freedesktop/NetworkManager/AccessPoint/613"
    Nov 23 20:25:46 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:20: Starting /usr/bin/pkla-check-authorization matej true true org.freedesktop.timedate1.set-timezone
    Nov 23 20:25:46 mitmanek systemd[1]: Started Session 237 of user matej.
    Nov 23 20:25:46 mitmanek systemd[1]: Starting Session 237 of user matej.
    Nov 23 20:25:48 mitmanek transmission-daemon[10461]: lightthatfailed_1001_librivox Starting IPv4 DHT announce (firewalled, 195 nodes) (tr-dht.c:577)
    Nov 23 20:25:56 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:21: Error: Error spawning helper: Timed out after 10 seconds (g-io-error-quark, 24)
    Nov 23 20:25:56 mitmanek polkitd[1240]: Error evaluating authorization rules
    Nov 23 20:26:44 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:20: Starting /usr/bin/pkla-check-authorization matej true true org.gnome.controlcenter.datetime.configure
    Nov 23 20:26:54 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:21: Error: Error spawning helper: Timed out after 10 seconds (g-io-error-quark, 24)
    Nov 23 20:26:54 mitmanek polkitd[1240]: Error evaluating authorization rules
    Nov 23 20:27:11 mitmanek packagekitd[4323]: pk_transaction_status_changed_emit: assertion 'PK_IS_TRANSACTION (transaction)' failed
    Nov 23 20:27:11 mitmanek packagekitd[4323]: g_dbus_connection_emit_signal: assertion 'object_path != NULL && g_variant_is_object_path (object_path)' failed
    Nov 23 20:27:11 mitmanek packagekitd[4323]: g_dbus_connection_emit_signal: assertion 'object_path != NULL && g_variant_is_object_path (object_path)' failed
    Nov 23 20:27:11 mitmanek packagekitd[4323]: instance with invalid (NULL) class pointer
    Nov 23 20:27:11 mitmanek packagekitd[4323]: g_signal_emit_valist: assertion 'G_TYPE_CHECK_INSTANCE (instance)' failed
    Nov 23 20:27:21 mitmanek NetworkManager[1313]: <debug> [1479929241.8895] device[0x7f119de2c010] (wlp3s0): add_pending_action (1): 'scan'
    Nov 23 20:27:21 mitmanek NetworkManager[1313]: <debug> [1479929241.8914] device[0x7f119de2c010] (wlp3s0): remove_pending_action (0): 'scan'
    Nov 23 20:27:26 mitmanek NetworkManager[1313]: <trace> [1479929246.0661] platform-linux: event-notification: NEWLINK, seq 0: 3: wlp3s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 0 arp 1 wifi? not-init addrgenmode eui64 addr E8:B1:FC:02:42:ED rx:2,282 tx:2,288
    Nov 23 20:27:26 mitmanek NetworkManager[1313]: <trace> [1479929246.0689] exported-object[0x7f119de23390]: unexport: "/org/freedesktop/NetworkManager/AccessPoint/562"
    Nov 23 20:27:26 mitmanek NetworkManager[1313]: <trace> [1479929246.1029] exported-object[0x7f119de234d0]: export: "/org/freedesktop/NetworkManager/AccessPoint/614"
    Nov 23 20:27:26 mitmanek NetworkManager[1313]: <trace> [1479929246.1042] exported-object[0x7f119de9ba50]: export: "/org/freedesktop/NetworkManager/AccessPoint/615"
    Nov 23 20:27:26 mitmanek NetworkManager[1313]: <trace> [1479929246.1068] exported-object[0x7f119de23430]: export: "/org/freedesktop/NetworkManager/AccessPoint/616"
    Nov 23 20:27:36 mitmanek packagekitd[4323]: Error cancelling authorization check: Časový limit vypršel
    Nov 23 20:27:42 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:20: Starting /usr/bin/pkla-check-authorization matej true true org.freedesktop.timedate1.set-time
    Nov 23 20:27:42 mitmanek crond[32564]: (matej) INFO (Job execution of per-minute job scheduled for 20:20 delayed into subsequent minute 20:27. Skipping job run.)
    Nov 23 20:27:52 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:21: Error: Error spawning helper: Timed out after 10 seconds (g-io-error-quark, 24)
    Nov 23 20:27:52 mitmanek polkitd[1240]: Error evaluating authorization rules
    Nov 23 20:28:40 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:20: Starting /usr/bin/pkla-check-authorization matej true true org.freedesktop.packagekit.trigger-offline-update
    Nov 23 20:28:50 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:21: Error: Error spawning helper: Timed out after 10 seconds (g-io-error-quark, 24)
    Nov 23 20:28:50 mitmanek polkitd[1240]: Error evaluating authorization rules
    Nov 23 20:28:53 mitmanek systemd[1]: Created slice user-991.slice.
    Nov 23 20:28:53 mitmanek systemd[1]: Starting user-991.slice.
    Nov 23 20:28:53 mitmanek systemd[1]: Started Session 238 of user pcp.
    Nov 23 20:28:53 mitmanek systemd[1]: Starting Session 238 of user pcp.
    Nov 23 20:29:21 mitmanek NetworkManager[1313]: <debug> [1479929361.8885] device[0x7f119de2c010] (wlp3s0): add_pending_action (1): 'scan'
    Nov 23 20:29:21 mitmanek NetworkManager[1313]: <debug> [1479929361.8908] device[0x7f119de2c010] (wlp3s0): remove_pending_action (0): 'scan'
    Nov 23 20:29:25 mitmanek NetworkManager[1313]: <trace> [1479929365.8728] platform-linux: event-notification: NEWLINK, seq 0: 3: wlp3s0 <UP,LOWER_UP;broadcast,multicast,up,running,lowerup> mtu 0 arp 1 wifi? not-init addrgenmode eui64 addr E8:B1:FC:02:42:ED rx:2,282 tx:2,288
    Nov 23 20:29:25 mitmanek NetworkManager[1313]: <trace> [1479929365.8783] exported-object[0x7f11840021a0]: unexport: "/org/freedesktop/NetworkManager/AccessPoint/613"
    Nov 23 20:29:25 mitmanek NetworkManager[1313]: <trace> [1479929365.9152] exported-object[0x7f119de9b9b0]: export: "/org/freedesktop/NetworkManager/AccessPoint/617"
    Nov 23 20:29:25 mitmanek NetworkManager[1313]: <trace> [1479929365.9168] exported-object[0x7f119deb81b0]: export: "/org/freedesktop/NetworkManager/AccessPoint/618"
    Nov 23 20:29:25 mitmanek NetworkManager[1313]: <trace> [1479929365.9182] exported-object[0x7f119de23610]: export: "/org/freedesktop/NetworkManager/AccessPoint/619"
    Nov 23 20:29:25 mitmanek NetworkManager[1313]: <trace> [1479929365.9197] exported-object[0x7f119dd97610]: export: "/org/freedesktop/NetworkManager/AccessPoint/620"
    Nov 23 20:29:38 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:20: Starting /usr/bin/pkla-check-authorization matej true true org.freedesktop.packagekit.trigger-offline-update
    Nov 23 20:29:48 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:21: Error: Error spawning helper: Timed out after 10 seconds (g-io-error-quark, 24)
    Nov 23 20:29:48 mitmanek polkitd[1240]: Error evaluating authorization rules
    Nov 23 2

Version-Release number of selected component (if applicable):
polkit-0.112-9.el7.x86_64
PackageKit-1.1.4-1.el7.x86_64

How reproducible:
100%

Steps to Reproduce:
1. just run pkcon with operation requiring authorization (e.g., pkcon remove)
2.
3.

Actual results:
see above

Expected results:
authorization dialog jumps and asks for the password (it never happened)

Comment 2 Milos Malik 2016-11-24 14:42:53 UTC

Sometimes are the timeouts caused by SELinux.  Do you see any USER_AVCs?

# ausearch -m user_avc -i -ts today

Comment 3 Miloslav Trmač 2016-11-24 14:49:01 UTC

Yeah, and what polkit authorization agent is in use (what kind of session/desktop is this; or do you have a custom agent)? Do non-polkit D-Bus calls work?

>    Nov 23 20:29:38 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:20: Starting /usr/bin/pkla-check-authorization matej true true org.freedesktop.packagekit.trigger-offline-update
>    Nov 23 20:29:48 mitmanek polkitd[1240]: /etc/polkit-1/rules.d/49-polkit-pkla-compat.rules:21: Error: Error spawning helper: Timed out after 10 seconds (g-io-error-quark, 24)

OK, so that file has obviously been modified. Does the pkla-check-authorization command (or whatever line 21 actually starts) finish quickly, or hang as well? If it hangs, doing what?

Comment 4 Matěj Cepl 2016-11-24 23:30:56 UTC

mitmanek:~# ausearch -m AVC -ts yesterday
<no matches>
mitmanek:~# ausearch -m AVC -ts today
<no matches>
mitmanek:~# ausearch -m user_avc -ts yesterday
<no matches>
mitmanek:~# ausearch -m user_avc -ts today
<no matches>
mitmanek:~#

Comment 5 Matěj Cepl 2016-11-24 23:32:17 UTC

Created attachment 1224058 [details]
/var/log/audit/audit.log

Comment 6 Milos Malik 2016-11-25 06:40:42 UTC

Analysis of the audit.log revealed that some SELinux rules are needed:

allow colord_t systemd_hwdb_etc_t:file read; # already addressed in BZ#1373082

Following rules are not present in the latest selinux-policy build and are not mentioned in any other RHEL-7 selinux-policy bug:

allow geoclue_t avahi_t:dbus send_msg;
allow geoclue_t kernel_t:unix_dgram_socket sendto;
allow xdm_t mount_var_run_t:file getattr;

I'm going to file them as bugs, if you don't mind.

Comment 7 Matěj Cepl 2016-11-25 16:21:42 UTC

Sure, but could anyone of them break PolKit?

Comment 8 Milos Malik 2016-11-27 09:07:26 UTC

Most likely not.

Comment 10 Jan Rybar 2019-09-25 17:06:10 UTC

Hello, can you please verify that this bug persists?
I just checked that on rhel-7.7 VM and didn't see anything wrong.
Also, the errors I saw in your output suggest that helper failed to run (get spawned). Did you try to reinstall polkit or check that polkit-gnome (or other helper) is installed?
Please reopen the bug if you're still encountering the issue.

Note You need to log in before you can comment on or make changes to this bug.