Bug 1534873 - Fprintd timeout during user login
Summary: Fprintd timeout during user login
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: systemd
Version: 35
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: systemd-maint
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1719180 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-01-16 07:40 UTC by Ales Raszka
Modified: 2022-08-12 13:39 UTC (History)
19 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2022-08-12 13:39:17 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
strace output of "fprintd-list $USER" (36.15 KB, text/plain)
2020-08-22 08:47 UTC, Didier
no flags Details
strace output of "su" (101.83 KB, text/plain)
2020-08-22 08:51 UTC, Didier
no flags Details

Description Ales Raszka 2018-01-16 07:40:09 UTC
Description of problem:
After update to F27, I am facing issue during login to the system as a user. When a screen is locked (screen with the clock) and I hit any key to show password screen a system completely freeze for 15-20 seconds and after that time I am finally able to type my password.

Journalctl shows following error message:

Jan 16 08:19:36 araszka-rh gnome-shell[2622]: Failed to connect to Fprint service: Error calling StartServiceByName for net.reactivated.Fprint: Timeout was reached
Jan 16 08:19:36 araszka-rh dbus-daemon[981]: [system] Failed to activate service 'net.reactivated.Fprint': timed out (service_start_timeout=25000ms)


Version-Release number of selected component (if applicable):
libfprint-0.7.0-3.fc27.x86_64
fprintd-0.8.0-1.fc27.x86_64
fprintd-pam-0.8.0-1.fc27.x86_64


How reproducible:
always

Steps to Reproduce:
1. Lock a screen
2. Log in as a user
3.

Actual results:
System freeze for 15-20 second in the middle of lock screen and password screen

Expected results:
No delay

Additional info:
The bug is reproducible on my Lenovo Thinkpad T450s.

Comment 1 Christophe Fergeau 2018-01-17 14:38:36 UTC
Hitting that occasionally on my f27. Once it starts triggering, 'fprintd-list $username' triggers it too (it hangs for 25 seconds and dies with a service timeout rather than telling me "no device found).
Commenting out ProtectSystem=strict in /usr/lib/systemd/system/fprintd.service makes it go away

Comment 2 Christophe Fergeau 2018-01-17 14:58:49 UTC
Looking at fprintd strace/backtrace while it's stuck, I figured out it was trying to run statfs on some stale cifs mountpoints I had on my laptop. After unmounting them (and with an unmodified systemd service file), I no longer get hangs running 'fprintd-list $username'

Comment 3 Christophe Fergeau 2018-01-17 14:59:35 UTC
backtrace of fprintd while it's hung

#0  0x00007fbcdde84287 in statfs64 () from target:/lib64/libc.so.6
#1  0x00007fbcdde84309 in statvfs64 () from target:/lib64/libc.so.6
#2  0x00005627d4a130f7 in get_mount_flags (
    path=path@entry=0x5627d5f54710 "/media/synology/backup", 
    flags=flags@entry=0x7ffc8e276778) at ../src/basic/mount-util.c:314
#3  0x00005627d4a1577a in bind_remount_recursive_with_mountinfo (ro=true, 
    proc_self_mountinfo=<optimized out>, blacklist=<optimized out>, 
    prefix=<optimized out>) at ../src/basic/mount-util.c:489
#4  make_read_only (proc_self_mountinfo=<optimized out>, 
    blacklist=<optimized out>, m=<optimized out>)
    at ../src/core/namespace.c:803
#5  setup_namespace.constprop.59 (root_directory=<optimized out>, 
    root_image=<optimized out>, ns_info=<optimized out>, 
    read_write_paths=<optimized out>, read_only_paths=<optimized out>, 
    inaccessible_paths=<optimized out>, bind_mounts=<optimized out>, 
    n_bind_mounts=<optimized out>, tmp_dir=<optimized out>, 
    var_tmp_dir=<optimized out>, protect_home=<optimized out>, 
    protect_system=<optimized out>, mount_flags=<optimized out>, 
    dissect_image_flags=<optimized out>) at ../src/core/namespace.c:1115
#6  0x00005627d4a17654 in apply_mount_namespace.lto_priv.263 (
    u=0x5627d610b5b0, command=0x5627d606cc40, context=0x5627d610b9e0, 
    params=<optimized out>, runtime=<optimized out>)
    at ../src/core/execute.c:2002
#7  0x00005627d4a851f4 in exec_child.constprop.47 (unit=0x5627d610b5b0, 
    command=0x5627d606cc40, context=<optimized out>, params=0x7ffc8e277180, 
    runtime=<optimized out>, dcreds=<optimized out>, argv=<optimized out>, 
    socket_fd=<optimized out>, named_iofds=<optimized out>, 
    fds=<optimized out>, n_storage_fds=<optimized out>, 
    n_socket_fds=<optimized out>, files_env=<optimized out>, 
    user_lookup_fd=<optimized out>, exit_status=<optimized out>, 
    error_message=<optimized out>) at ../src/core/execute.c:2626
#8  0x00005627d4ab5060 in exec_spawn (unit=<optimized out>, 
    command=0x5627d606cc40, context=0x5627d610b9e0, params=<optimized out>, 
    runtime=0x0, dcreds=0x5627d610bd28, ret=0x7ffc8e277170)
    at ../src/core/execute.c:2983
#9  0x00005627d4a5801f in service_spawn (s=s@entry=0x5627d610b5b0, 
    c=<optimized out>, timeout=<optimized out>, 
    flags=flags@entry=(EXEC_APPLY_PERMISSIONS | EXEC_APPLY_CHROOT | EXEC_APPLY_TTY_STDIN | EXEC_PASS_FDS | EXEC_SET_WATCHDOG), _pid=_pid@entry=0x7ffc8e2772c4)
    at ../src/core/service.c:1375
#10 0x00005627d4a60c6c in service_enter_start (s=s@entry=0x5627d610b5b0)
    at ../src/core/service.c:1817
#11 0x00005627d4a61098 in service_enter_start_pre (s=0x5627d610b5b0)
    at ../src/core/service.c:1886
#12 service_start.lto_priv.375 (u=0x5627d610b5b0) at ../src/core/service.c:2099
#13 0x00005627d4a9ad3c in unit_start (u=0x5627d610b5b0)
    at ../src/core/unit.c:1647
#14 job_perform_on_unit.lto_priv.870 (j=0x7ffc8e2773a0)
    at ../src/core/job.c:535
#15 0x00005627d4ab83d8 in job_run_and_invalidate (j=<optimized out>)
    at ../src/core/job.c:600
#16 manager_dispatch_run_queue.lto_priv.881 (source=<optimized out>, 
    userdata=<optimized out>, userdata=<optimized out>)
    at ../src/core/manager.c:1621
#17 0x00007fbcdda6f4ba in source_dispatch (s=s@entry=0x5627d5f75930)
    at ../src/libsystemd/sd-event/sd-event.c:2312
#18 0x00007fbcdda6f7da in sd_event_dispatch (e=e@entry=0x5627d5f75c10)
    at ../src/libsystemd/sd-event/sd-event.c:2631
#19 0x00007fbcdda6f957 in sd_event_run (e=0x5627d5f75c10, 
    timeout=18446744073709551615) at ../src/libsystemd/sd-event/sd-event.c:2690
#20 0x00005627d4abc5a2 in manager_loop (m=0x5627d5f77520)
    at ../src/core/manager.c:2291
#21 0x00005627d4a1ece1 in main (argc=5, argv=<optimized out>)
    at ../src/core/main.c:1937

Comment 4 Christophe Fergeau 2018-10-08 10:19:34 UTC
Still an issue with f29

Comment 5 Bastien Nocera 2018-10-08 11:44:31 UTC
I don't know why systemd is trying to bind remount the backup share on your NAS, but it probably (still) shouldn't be doing that.

Comment 6 Robert Buchholz 2019-06-04 07:16:42 UTC
Same on f30.

Comment 7 Michael Clayton 2019-06-05 15:00:14 UTC
I'm also seeing this on F30.  It just started yesterday for me.

Comment 8 Matt Heck 2019-06-07 23:44:42 UTC
Seeing this problem immediately after "dnf system-upgrade" upgrade from F29 to F30:

Jun 07 16:23:59 * gnome-shell[8386]: Failed to connect to Fprint service: Error calling StartServiceByName for net.reactivated.Fprint: Timeout was reached
Jun 07 16:24:04 * dbus-broker-launch[1581]: avc:  received policyload notice (seqno=2)
Jun 07 16:24:24 * gnome-shell[8386]: Failed to connect to Fprint service: Error calling StartServiceByName for net.reactivated.Fprint: Timeout was reached
Jun 07 16:24:49 * gnome-shell[8386]: Failed to connect to Fprint service: Error calling StartServiceByName for net.reactivated.Fprint: Timeout was reached
Jun 07 16:24:53 * gdm-password][15166]: gkr-pam: unlocked login keyring
Jun 07 16:24:53 * audit[15166]: USER_AUTH pid=15166 uid=0 auid=1000 ses=2 subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 msg='op=PAM:authentication grantors=pam_succeed_if,pam_localuser,pam_unix,pam_gnome_keyring acct="myusername" exe="/usr/libexec/gdm-session-worker" hostname=myhostname.mysubdomain.mydomain.com addr=? terminal=/dev/tty2 res=success'
Jun 07 16:24:53 * audit[15166]: USER_ACCT pid=15166 uid=0 auid=1000 ses=2 subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 msg='op=PAM:accounting grantors=pam_unix,pam_localuser acct="myusername" exe="/usr/libexec/gdm-session-worker" * addr=? terminal=/dev/tty2 res=success'
Jun 07 16:24:53 * audit[15166]: CRED_REFR pid=15166 uid=0 auid=1000 ses=2 subj=system_u:system_r:xdm_t:s0-s0:c0.c1023 msg='op=PAM:setcred grantors=pam_localuser,pam_unix,pam_gnome_keyring acct="myusername" exe="/usr/libexec/gdm-session-worker" hostname=myhostname.mysubdomain.mydomain.com addr=? terminal=/dev/tty2 res=success'
Jun 07 16:24:53 * gsd-power[8503]: up_client_get_on_battery: assertion 'UP_IS_CLIENT (client)' failed
Jun 07 16:24:53 * NetworkManager[1383]: <info>  [1559949893.8365] agent-manager: req[0x5601e75a92f0, :1.306/org.gnome.Shell.NetworkAgent/1000]: agent registered


Saw a bunch of other problems, too, related to really slow sudo execution, most of which seemed to resolve by banging around on nsswitch.conf and sssd.  Still not entirely sure what broke, but it's beginning to seem like at least one, possibly several, authentication-related services are trying to check things that have slow timeouts.  Notably, the sudo-related problems happen even in runlevel 2-- that is, before the network is up-- which means all the people who are totally convinced it's some kind of network configuration problem are almost certainly wrong.

So, it's been hard to tell whether this is multiple problems with the same root cause, multiple unrelated problems, or something weirder.

What's frustrating is that variations on these problems, across multiple distros, seem to go back years and years.  I suspect that the slow sudo issue that is NOT a network configuration issue, and the Gnome screen lock that doesn't display a password prompt for a long time, may both have the same root cause, and that this has been a seven year long, multi-project finger-pointing circle-jerk.

It would be nice to finally figure out WTF is so damn brittle that so many versions of so many distros keep breaking it.

Comment 9 Matt Heck 2019-06-08 00:05:24 UTC
WORKAROUND:
For me,

sudo dnf remove fprintd

followed by a reboot resolves this-- as long as you don't actually need fingerprint login.  (I certainly don't; this desktop doesn't even have the hardware for it, and never did.)

However, again, I suspect the actual culprit is a configuration problem, or bad multi-package interaction, involving a lower-level authentication system.

Nonetheless, this is worth a try, if you need a fix right now (which, for a bug like this, you probably do) and don't absolutely require fingerprint login.  If you do, try reinstalling fprintd AFTER uninstalling and rebooting, and let us all know if it starts working again.

Comment 10 Adam Williamson 2019-06-08 00:50:12 UTC
I've seen this too, but from a long time ago (like Christophe), not starting with F30 (like Matt and Michael). I figured out that removing fprintd helped a while back.

Comment 11 Bastien Nocera 2019-06-11 11:22:40 UTC
*** Bug 1719180 has been marked as a duplicate of this bug. ***

Comment 12 Samuel Sieb 2019-06-26 05:51:00 UTC
The strange part for me is if I run "systemctl start fprintd", it starts successfully and everything works until it gets automatically stopped again after a short delay.  The problem is something specific to the way it's being started by other processes.

Comment 13 Bastien Nocera 2019-08-19 10:30:31 UTC
(In reply to Christophe Fergeau from comment #3)
> backtrace of fprintd while it's hung
> 
<snip>
> #19 0x00007fbcdda6f957 in sd_event_run (e=0x5627d5f75c10, 
>     timeout=18446744073709551615) at
> ../src/libsystemd/sd-event/sd-event.c:2690
> #20 0x00005627d4abc5a2 in manager_loop (m=0x5627d5f77520)
>     at ../src/core/manager.c:2291
> #21 0x00005627d4a1ece1 in main (argc=5, argv=<optimized out>)
>     at ../src/core/main.c:1937

This is clearly systemd, pre-fork. This code isn't from fprintd, and if stuff hangs before fprintd is even forked, I don't see how blaming it would help anything.

Comment 14 Ben Cotton 2020-04-30 21:19:53 UTC
This message is a reminder that Fedora 30 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora 30 on 2020-05-26.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
Fedora 'version' of '30'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 30 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 15 Ben Cotton 2020-05-26 14:29:15 UTC
Fedora 30 changed to end-of-life (EOL) status on 2020-05-26. Fedora 30 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

Comment 16 Didier 2020-08-22 07:57:11 UTC
Encountering this issue on an up-to-date F32 : 

systemd-245.7-1.fc32.x86_64
fprintd-1.90.1-1.fc32.x86_64

Comment 17 Didier 2020-08-22 07:58:48 UTC
Can this bz be reopened, or do I need to file a new bug report against F32 ?

Comment 18 Didier 2020-08-22 08:46:57 UTC
# strace -o /tmp/strace_fprintd-list.out -tt -f fprintd-list $USER
list_devices failed: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken.

strace_fprintd-list.out in attachment ; command hangs at
'2570072 10:44:27.207763 restart_syscall(<... resuming interrupted restart_syscall ...>'

Comment 19 Didier 2020-08-22 08:47:53 UTC
Created attachment 1712228 [details]
strace output of "fprintd-list $USER"

Comment 20 Didier 2020-08-22 08:51:11 UTC
$ strace -o /tmp/strace_su.out -tt -f su

strace_su.out in attachment ; command hangs at
'2571952 10:49:47.809422 ppoll([{fd=5, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999930000}, NULL, 8'

Comment 21 Didier 2020-08-22 08:51:40 UTC
Created attachment 1712229 [details]
strace output of "su"

Comment 22 Didier 2020-08-22 08:56:22 UTC
Note : this behaviour usually starts to occur after a couple of days uptime (this is on a Dell XPS7390 2-in-1 with unrecognized fingerprint reader), for every action which requires authentication (su, sudo, virt-manager, screensaver unlocking).


journalctl error message (for the "su" example from comment#20) :

Aug 22 10:50:12 mymachine su[2571952]: pam_fprintd(su:auth): GetDevices failed: Connection timed out

Comment 23 Adam Pribyl 2021-06-02 07:27:51 UTC
Still happens on F34

Comment 24 Robert Hubinak 2022-01-12 21:07:07 UTC
Happens on F35 with sway:

Jan 12 20:11:26 laptop swaylock[5947]: pam_fprintd(swaylock:auth): GetDevices failed: Connection timed out

Comment 25 Ben Cotton 2022-05-12 16:34:54 UTC
This message is a reminder that Fedora Linux 34 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora Linux 34 on 2022-06-07.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
'version' of '34'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, change the 'version' 
to a later Fedora Linux version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora Linux 34 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora Linux, you are encouraged to change the 'version' to a later version
prior to this bug being closed.

Comment 26 Adam Williamson 2022-05-14 00:29:31 UTC
Updating to 35 per Robert's comment.

Comment 27 David Tardon 2022-08-12 13:39:17 UTC
(In reply to Christophe Fergeau from comment #1)
> Hitting that occasionally on my f27. Once it starts triggering,
> 'fprintd-list $username' triggers it too (it hangs for 25 seconds and dies
> with a service timeout rather than telling me "no device found).
> Commenting out ProtectSystem=strict in
> /usr/lib/systemd/system/fprintd.service makes it go away

> Looking at fprintd strace/backtrace while it's stuck, I figured out it was
> trying to run statfs on some stale cifs mountpoints I had on my laptop.
> After unmounting them (and with an unmodified systemd service file), I no
> longer get hangs running 'fprintd-list $username'

This was fixed in v243 (https://github.com/systemd/systemd/pull/12852).


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