sudo is fast again

A big hammer solution:

[root@quaco ~]# rpm -e fprintd fprintd-pam
[error] [/etc/nsswitch.conf] is not a symbolic link!
[error] [/etc/nsswitch.conf] was not created by authselect!
[error] Unexpected changes to the configuration were detected.
[error] Refusing to activate profile unless those changes are removed or overwrite is requested.
Unable to disable feature [17]: File exists
[root@quaco ~]#

The warnings are not that reassuring, trying to use authselect to check the config also doesn’t bring extra confidence:

[root@quaco ~]# authselect check
[error] [/etc/nsswitch.conf] is not a symbolic link!
[error] [/etc/nsswitch.conf] was not created by authselect!
Current configuration is not valid. It was probably modified outside authselect.

The fprintd is still in the config files:

[root@quaco ~]# grep fprintd /etc/pam.d/system-auth
auth sufficient pam_fprintd.so
[root@quaco ~]#

But since it is not installed, I get my fast sudo again, back to work.

What is ‘sudo su -‘ doing?

Out of the blue sudo started taking a long time to ask for my password, so I sleeptyped:

$ strace sudo su -

sudo: effective uid is not 0, is /usr/bin/sudo on a file system with the 'nosuid' option set or an NFS file system without root privileges?
$

Oops, perhaps it would be a good time for me to try using ‘perf trace’, so I tried:

perf trace --duration 5000 --call-graph=dwarf

To do system wide syscall tracing looking for syscalls taking more than 5 seconds to complete, together with DWARF callchains.

And after tweaking that –duration parameter and using –filter-pids to exclude some long timeout processes that seemed unrelated, and even without using ‘-e \!futex’ to exclude some syscalls taking that long to complete and again, looking unrelated to sudo’s being stuck I got the clue I needed from this entry:


12345.846 (25024.785 ms): sudo/3571 poll(ufds: 0x7ffdcc4376a0, nfds: 1, timeout_msecs: 25000) = 0 (Timeout)
__GI___poll (inlined)
[0x30dec] (/usr/lib64/libdbus-1.so.3.19.11)
[0x2fab0] (/usr/lib64/libdbus-1.so.3.19.11)
[0x176cb] (/usr/lib64/libdbus-1.so.3.19.11)
[0x1809f] (/usr/lib64/libdbus-1.so.3.19.11)
[0x1518b] (/usr/lib64/libdbus-glib-1.so.2.3.4)
dbus_g_proxy_call (/usr/lib64/libdbus-glib-1.so.2.3.4)
pam_sm_authenticate (/usr/lib64/security/pam_fprintd.so)
[0x41f1] (/usr/lib64/libpam.so.0.84.2)
pam_authenticate (/usr/lib64/libpam.so.0.84.2)
[0xb703] (/usr/libexec/sudo/sudoers.so)
[0xa8f4] (/usr/libexec/sudo/sudoers.so)
[0xc754] (/usr/libexec/sudo/sudoers.so)
[0x24a83] (/usr/libexec/sudo/sudoers.so)
[0x1d759] (/usr/libexec/sudo/sudoers.so)
[0x6ef3] (/usr/bin/sudo)
__libc_start_main (/usr/lib64/libc-2.29.so)
[0x887d] (/usr/bin/sudo)

So its about PAM, authentication using some fprintd module, and sudo polls with a timeout of 25000 msecs, no wonder when I first tried with –failure, to ask just for syscalls that returned some error I wasn’t getting anything…

Lets see what is this thing:

[root@quaco ~]# rpm -qf /usr/lib64/security/pam_fprintd.so
fprintd-pam-0.9.0-1.fc30.x86_64
[root@quaco ~]# rpm -q --qf "%{description}\n" fprintd-pam
PAM module that uses the fprintd D-Bus service for fingerprint
authentication.
[root@quaco ~]

I don’t recall enabling this and from a quick look this t480s doesn’t seem to have any fingerprint reader, lets see how to disable this on this Fedora 30 system…

Pahole in the news

Found another interesting article, this time mentioning a tool I wrote long ago and that, at least for kernel object files, has been working for a long time without much care on my part: pahole, go read a bit about it at Will Cohen’s “How to avoid wasting megabytes of memory a few bytes at a time” article.

Guess I should try running a companion script that tries to process all .o files in debuginfo packages to see how bad it is for non-kernel files, with all the DWARF changes over these years…

Looking for users of new syscalls

Recently Linux got a new syscall to get extended information about files, a super ‘stat’, if you will, read more about it at LWN.

So I grabbed the headers with the definitions for the statx arguments to tools/include/ so that ‘perf trace’ can use them to beautify, i.e. to appear as
a bitmap of strings, as described in this cset.

To test it I used one of things ‘perf trace’ can do and that ‘strace’ does not: system wide stracing. To look if any of the programs running on my machine was using the new syscall I simply did, using strace-like syntax:

# perf trace -e statx 

After a few minutes, nothing… So this fedora 25 system isn’t using it in any of the utilities I used in these moments, not surprising, glibc still needs wiring statx up.

So I found out about samples/statx/test-statx.c, and after installing the kernel headers and pointing the compiler to where those files were installed, I restarted that system wide ‘perf trace’ session and ran the test program, much better:

# trace -e statx 16612.967 ( 0.028 ms): statx/562 statx(dfd: CWD, filename: /etc/passwd, flags: SYMLINK_NOFOLLOW, mask: TYPE|MODE|NLINK|UID|GID|ATIME|MTIME|CTIME|INO|SIZE|BLOCKS|BTIME, buffer: 0x7ffef195d660) = 0 33064.447 ( 0.011 ms): statx/569 statx(dfd: CWD, filename: /tmp/statx, flags: SYMLINK_NOFOLLOW|STATX_FORCE_SYNC, mask: TYPE|MODE|NLINK|UID|GID|ATIME|MTIME|CTIME|INO|SIZE|BLOCKS|BTIME, buffer: 0x7ffc5484c790) = 0 36050.891 ( 0.023 ms): statx/576 statx(dfd: CWD, filename: /etc/motd, flags: SYMLINK_NOFOLLOW, mask: BTIME, buffer: 0x7ffeb18b66e0) = 0 38039.889 ( 0.023 ms): statx/584 statx(dfd: CWD, filename: /home/acme/.bashrc, flags: SYMLINK_NOFOLLOW, mask: TYPE|MODE|NLINK|UID|GID|ATIME|MTIME|CTIME|INO|SIZE|BLOCKS|BTIME, buffer: 0x7fff1db0ea90) = 0 ^C#

Ah, to get filenames fetched we need to put in place a special probe, that will collect filenames passed to the kernel right after the kernel copies it from user memory:

[root@jouet ~]# perf probe 'vfs_getname=getname_flags:72 pathname=result->name:string' Added new event: probe:vfs_getname    (on getname_flags:72 with pathname=result->name:string) You can now use it in all perf tools, such as: perf record -e probe:vfs_getname -aR sleep 1 [root@jouet ~]# trace -e open touch /etc/passwd 0.024 ( 0.011 ms): touch/649 open(filename: /etc/ld.so.cache, flags: CLOEXEC) = 3 0.056 ( 0.018 ms): touch/649 open(filename: /lib64/libc.so.6, flags: CLOEXEC) = 3 0.481 ( 0.014 ms): touch/649 open(filename: /usr/lib/locale/locale-archive, flags: CLOEXEC) = 3 0.553 ( 0.012 ms): touch/6649 open(filename: /etc/passwd, flags: CREAT|NOCTTY|NONBLOCK|WRONLY, mode: IRUGO|IWUGO) = 3 [root@jouet ~]# 

Make sure you have CONFIG_DEBUG_INFO set in your kernel build or that the matching debuginfo packages are installed. This needs to be done just once per boot, ‘perf trace’ will find it in place and use it.

Lastly, if ‘perf’ is hardlinked to ‘trace’, then the later will be the same as ‘perf trace’.