Bug 1378379

Thanks for your report.

My (ps -alt) uses a completely different output, no idea what the above means; anyway, polkit does create a pkla-check-auth child per each request, so mere presence or such processes does not necessarily indicate a problem.


Anyway, I’m afraid I can’t reproduce this; so instead of chasing a guess, can you attach the entire journalctl output around the time of your (su -) attempt?

Also reassigning to pam as the primary component known to be in common between su and screen locking.

Also can you attach your /etc/pam.d/system-auth?

(In reply to Miloslav Trmač from comment #1)
> Thanks for your report.
> 
> My (ps -alt) uses a completely different output, no idea what the above
> means; anyway, polkit does create a pkla-check-auth child per each request,
> so mere presence or such processes does not necessarily indicate a problem.
> 
> 
> Anyway, I’m afraid I can’t reproduce this; so instead of chasing a guess,
> can you attach the entire journalctl output around the time of your (su -)
> attempt?
> 
> Also reassigning to pam as the primary component known to be in common
> between su and screen locking.

I am trying to trace what I did to my system. I did add the finger print daemon
to it (I've got a Lenovo t450s which has a thumbprint reader) and it was after that was added that I noticed the slowness. I did remove the fprint reader but I reckon some rules could have been added into the pam for that.

Here's my current /etc/pam.d/system-auth:

[harish@gillman ~]$ cat /etc/pam.d/system-auth
#%PAM-1.0
# This file is auto-generated.
# User changes will be destroyed the next time authconfig is run.
auth        required      pam_env.so
auth        sufficient    pam_fprintd.so
auth        [default=1 success=ok] pam_localuser.so
auth        [success=done ignore=ignore default=die] pam_unix.so nullok try_firs
t_pass
auth        requisite     pam_succeed_if.so uid >= 1000 quiet_success
auth        sufficient    pam_sss.so forward_pass
auth        required      pam_deny.so

account     required      pam_unix.so
account     sufficient    pam_localuser.so
account     sufficient    pam_succeed_if.so uid < 1000 quiet
account     [default=bad success=ok user_unknown=ignore] pam_sss.so
account     required      pam_permit.so

password    requisite     pam_pwquality.so try_first_pass local_users_only retry
=3 authtok_type=
password    sufficient    pam_unix.so sha512 shadow nullok try_first_pass use_au
thtok
password    sufficient    pam_sss.so use_authtok
password    required      pam_deny.so

session     optional      pam_keyinit.so revoke
session     required      pam_limits.so
-session     optional      pam_systemd.so
session     optional      pam_mkhomedir.so umask=0077
session     [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid
session     required      pam_unix.so
session     optional      pam_sss.so

(In reply to Tomas Mraz from comment #2)
> Also can you attach your /etc/pam.d/system-auth?

i've attached the /etc/pam.d/system-auth in the reply to the previous comment.

i see that pam_fprintd.so is in it. i've just commented it out and it seems to be working better now. "su -" and gnome screenlock is not taking as long as it used to.

So, if appears that the dnf remove fprintd did not remove the pam entry.

I am Ok to close this report.

I did a systemctl restart polkit.service and the delay is still there but not as much as it was before. Will continue to investigate.

Been checking and monitoring the system and regrettably, the delay still is there and I am noticing that there are lots of defunct polkitd processes running as indicated in the initial report.

Some observations:
a) Clicking on the GNOME top right hand corner to invoke the VPN option, does not produce the usual VPN password dialog box.
b) I have to use the CLI to connect to the vpn that I need to connect to.
c) Even when "systemctl restart polkitd.service", the NetworkManager's dialog box does not appear, but it DOES clean out the defunct polkitd processes.

I am not able to figure out what else I need to check. Appreciate any pointers.

Created attachment 1206764 [details]
screenshot shoing the output of "ps -ef|grep polkit"

this is the output of ps -ef|grep polkit.

the pkla-check-authorization goes into a defunct mode and not sure why.

(man ps):
>       Processes marked <defunct> are dead processes (so-called "zombies")
>       that remain because their parent has not destroyed them properly.
>       These processes will be destroyed by init(8) if the parent process
>       exits.

This just means that pkla-c-a has terminated, and it is quite uninteresting that these processes are being created and terminate; a new process is created for every polkit authorization request and terminates after returning one answer. It _might_ be interesting if polkitd (not pkla-c-a) were slow/hanging and failing to clean them up.

(In reply to Miloslav Trmač from comment #8)
> (man ps):
> >       Processes marked <defunct> are dead processes (so-called "zombies")
> >       that remain because their parent has not destroyed them properly.
> >       These processes will be destroyed by init(8) if the parent process
> >       exits.
> 
> This just means that pkla-c-a has terminated, and it is quite uninteresting
> that these processes are being created and terminate; a new process is
> created for every polkit authorization request and terminates after
> returning one answer. It _might_ be interesting if polkitd (not pkla-c-a)
> were slow/hanging and failing to clean them up.

Understood. But it seems to be just lingering in the process table. If the task is done, it shouldn't it clean up? 

What I have been doing is to restart polkit.service to clean up the defunct processes.

> If the task is done, it shouldn't it clean up? 

Oh, sure; but it does work for me in ordinary use. So, please start with providing the requested logs, and if that doesn’t help, we might need to figure out a way to reproduce this.

Hi Miloslav, 

I am experiencing similar problem on Fedora 25 workstation. My case is sudo takes long time(several minutes) to return after system been up for around 5 days.


- ps showed there were tons of:

polkitd  12813  0.0  0.0      0     0 ?        Z    11:05   0:00 [pkla-check-auth] <defunct>
polkitd  12818  0.0  0.0      0     0 ?        Z    11:06   0:00 [pkla-check-auth] <defunct>


- /var/log/secure showed:

Nov 30 11:25:04 localhost systemd: pam_unix(systemd-user:session): session opened for user pcp by (uid=0)
Nov 30 11:25:54 localhost systemd: pam_unix(systemd-user:session): session closed for user pcp
Nov 30 11:28:04 localhost systemd: pam_unix(systemd-user:session): session opened for user pcp by (uid=0)

...

Dec  4 21:28:53 localhost systemd: pam_unix(systemd-user:session): session closed for user pcp
Dec  4 21:55:07 localhost systemd: pam_unix(systemd-user:session): session opened for user pcp by (uid=0)
Dec  4 21:56:27 localhost systemd: pam_unix(systemd-user:session): session closed for user pcp
Dec  4 21:57:25 localhost polkitd[959]: /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)
Dec  4 21:57:25 localhost polkitd[959]: Error evaluating authorization rules
Dec  4 21:58:23 localhost polkitd[959]: /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)
Dec  4 21:58:23 localhost polkitd[959]: Error evaluating authorization rules
Dec  4 22:02:18 localhost crond[2170]: pam_systemd(crond:session): Failed to create session: Connection timed out
Dec  4 22:03:01 localhost polkitd[959]: /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)



Any info you want me to provide?

> Any info you want me to provide?

> can you attach the entire journalctl output around the time of your (su -) attempt?

(In reply to Miloslav Trmač from comment #12)
> > Any info you want me to provide?
> 
> > can you attach the entire journalctl output around the time of your (su -) attempt?

su - worked fine to me, it returned with prompt for password immediately. Only sudo caused lag in my case.

I issued:
$ date; sudo ls /boot
Tue Dec  6 09:25:51 CST 2016

then watched journalctl:

-- Logs begin at Fri 2015-12-25 08:47:23 CST, end at Tue 2016-12-06 09:29:18 CST. --
Dec 06 09:29:18 localhost.localdomain polkit-mate-aut[3522]: Error enumerating temporary authorizations: Timeout was reached
Dec 06 09:29:18 localhost.localdomain crond[31698]: pam_systemd(crond:session): Failed to create session: Connection timed out
Dec 06 09:28:53 localhost.localdomain systemd[1]: Started Session 1101 of user pcp.
Dec 06 09:28:53 localhost.localdomain systemd[1]: Starting User Manager for UID 982...
Dec 06 09:28:53 localhost.localdomain systemd[1]: Created slice User Slice of pcp.
Dec 06 09:28:51 localhost.localdomain audit[31768]: CRED_DISP pid=31768 uid=0 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='
Dec 06 09:28:51 localhost.localdomain audit[31768]: USER_END pid=31768 uid=0 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='o
Dec 06 09:28:51 localhost.localdomain sudo[31768]: pam_unix(sudo:session): session closed for user root
Dec 06 09:28:51 localhost.localdomain sudo[31768]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 06 09:28:51 localhost.localdomain audit[31768]: USER_START pid=31768 uid=0 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg=
Dec 06 09:28:51 localhost.localdomain sudo[31768]: pam_systemd(sudo:session): Cannot create session: Already occupied by a session
Dec 06 09:28:51 localhost.localdomain sudo[31768]:  chayang : TTY=pts/6 ; PWD=/home/chayang ; USER=root ; COMMAND=/bin/ls /boot
Dec 06 09:28:51 localhost.localdomain audit[31768]: CRED_REFR pid=31768 uid=0 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='
Dec 06 09:28:51 localhost.localdomain audit[31768]: USER_CMD pid=31768 uid=1000 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg
Dec 06 09:28:51 localhost.localdomain audit[31768]: USER_ACCT pid=31768 uid=1000 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 ms
Dec 06 09:28:51 localhost.localdomain audit[31768]: USER_AUTH pid=31768 uid=1000 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 ms
Dec 06 09:28:18 localhost.localdomain /usr/libexec/gdm-x-session[3320]: [4951:4985:1206/092818:ERROR:connection_factory_impl.cc(367)] Failed to connect to MCS
Dec 06 09:28:18 localhost.localdomain /usr/libexec/gdm-x-session[3320]: [4951:4985:1206/092818:ERROR:socket_stream.cc(210)] Closing stream with result -100
Dec 06 09:28:01 localhost.localdomain audit[31798]: CRED_ACQ pid=31798 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg=
Dec 06 09:28:01 localhost.localdomain audit[31798]: USER_ACCT pid=31798 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:crond_t:s0-s0:c0.c1023 msg
Dec 06 09:25:46 localhost.localdomain sudo[31759]: pam_unix(sudo:auth): auth could not identify password for [chayang]
Dec 06 09:25:46 localhost.localdomain audit[31759]: USER_CMD pid=31759 uid=1000 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg
Dec 06 09:25:46 localhost.localdomain audit[31759]: USER_AUTH pid=31759 uid=1000 auid=1000 ses=3 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 ms
Dec 06 09:25:46 localhost.localdomain sudo[31759]: pam_unix(sudo:auth): conversation failed

(In reply to Miloslav Trmač from comment #12)
> > Any info you want me to provide?
> 
> > can you attach the entire journalctl output around the time of your (su -) attempt?

Anything else I could provide in order for debugging?

I don't see this anymore so I am OK for it to be closed.