After upgrading to systemd-245.5 I could not log in to my desktop anymore. The exact symptom was pretty bizarre: trying to log in on a TTY, the system would accept my username and password, but would then apparently stall; hitting Ctrl-C would then initiate a new login prompt. A cursory glance at the system journal didn't give any hints as to what was wrong, just that the login was apparently successful (this was further indicated by every further login attempt showing the time of the previous attempt as the time of last login). After some research I finally narrowed it down to systemd-userdbd, and saw the following log entries that helped verify that idea: $ journalctl --since yesterday --grep pam [...] Jul 31 23:31:48 thetick systemd[231112]: pam_systemd(systemd-user:session): Failed to parse JSON user record: Invalid argument [...] (Note that these only appeared a handful of times, and I didn't notice them when trying to log in immediately after the upgrade.) It turns out that masking systemd-userdbd.service made it possible for me to log in successfully again. Note that I know pretty much nothing about systemd's userdb feature, maybe something is supposed to happen post-upgrade to make it "just work". Interestingly, my openSUSE TW laptop does *not* have systemd-userdbd installed; it looks as if it's not even packaged (neither is homed). I think this whole experience gives some extra motivation for implementing https://bugs.gentoo.org/729210. Reproducible: Always Steps to Reproduce: 1. Upgrade to sys-apps/systemd-245.5. 2. Reboot. 3. Try to log in. Actual Results: Log in fails with no visible error message. Expected Results: Log in succeeds. # emerge --info sys-apps/systemd Portage 2.3.103 (python 3.7.8-final-0, default/linux/amd64/17.1/desktop/plasma/systemd, gcc-9.3.0, glibc-2.30-r8, 5.4.48-gentoo x86_64) ================================================================= System Settings ================================================================= System uname: Linux-5.4.48-gentoo-x86_64-AMD_Athlon-tm-_64_X2_Dual_Core_Processor_4200+-with-gentoo-2.6 KiB Mem: 8159760 total, 158588 free KiB Swap: 4193280 total, 3777024 free Timestamp of repository gentoo: Fri, 31 Jul 2020 21:35:18 +0000 Head commit of repository gentoo: d5b041b212d4cc334ec9eb746f1053870b9182fb Timestamp of repository audio-overlay: Fri, 24 Jul 2020 21:43:21 +0000 Head commit of repository audio-overlay: 219c64db452cc6bd80cd6762e2326e83e008ef72 Head commit of repository flatpak-overlay: 26c396aef4d2f8908eea9b3ad2ccf7dc843a0887 sh dash 0.5.10.2-r1 ld GNU ld (Gentoo 2.33.1 p2) 2.33.1 app-shells/bash: 5.0_p17::gentoo dev-java/java-config: 2.3.1::gentoo dev-lang/perl: 5.30.3::gentoo dev-lang/python: 2.7.18-r1::gentoo, 3.7.8-r2::gentoo, 3.8.4-r1::gentoo dev-util/cmake: 3.16.5::gentoo sys-apps/baselayout: 2.6-r1::gentoo sys-apps/sandbox: 2.18::gentoo sys-devel/autoconf: 2.13-r1::gentoo, 2.69-r4::gentoo sys-devel/automake: 1.16.1-r1::gentoo sys-devel/binutils: 2.33.1-r1::gentoo sys-devel/gcc: 9.3.0-r1::gentoo sys-devel/gcc-config: 2.3.1::gentoo sys-devel/libtool: 2.4.6-r6::gentoo sys-devel/make: 4.2.1-r4::gentoo sys-kernel/linux-headers: 5.4-r1::gentoo (virtual/os-headers) sys-libs/glibc: 2.30-r8::gentoo Repositories: gentoo location: /var/db/repos/gentoo sync-type: git sync-uri: https://anongit.gentoo.org/git/repo/sync/gentoo.git priority: -1000 sync-git-verify-commit-signature: true audio-overlay location: /var/db/repos/audio-overlay sync-type: git sync-uri: https://github.com/gentoo-mirror/audio-overlay.git masters: gentoo mjoliet location: /home/marcec/projects/mjoliet-overlay masters: gentoo flatpak-overlay location: /var/db/repos/flatpak-overlay sync-type: git sync-uri: https://github.com/fosero/flatpak-overlay.git masters: gentoo priority: 50 Installed sets: @audio, @desktop-apps, @desktop-base, @desktop-plasma, @devel-audio, @devel-base, @devel-gentoo, @devel-misc, @games, @latex, @local-marcec, @phone, @science, @sys-base, @sys-utils, @temp ACCEPT_KEYWORDS="amd64" ACCEPT_LICENSE="@FREE" CBUILD="x86_64-pc-linux-gnu" CFLAGS="-O2 -march=native -pipe" CHOST="x86_64-pc-linux-gnu" CONFIG_PROTECT="/etc /usr/share/config /usr/share/gnupg/qualified.txt" CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/dconf /etc/env.d /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo /etc/texmf/language.dat.d /etc/texmf/language.def.d /etc/texmf/updmap.d /etc/texmf/web2c" CXXFLAGS="-O2 -march=native -pipe" DISTDIR="/var/cache/distfiles" EMERGE_DEFAULT_OPTS="--with-bdeps=y --quiet-build=y --nospinner --jobs 2 --load-average 4 --keep-going" ENV_UNSET="DBUS_SESSION_BUS_ADDRESS DISPLAY GOBIN GOPATH PERL5LIB PERL5OPT PERLPREFIX PERL_CORE PERL_MB_OPT PERL_MM_OPT XAUTHORITY XDG_CACHE_HOME XDG_CONFIG_HOME XDG_DATA_HOME XDG_RUNTIME_DIR" FCFLAGS="-O2 -pipe" FEATURES="assume-digests binpkg-docompress binpkg-dostrip binpkg-logs config-protect-if-modified distlocks ebuild-locks fixlafiles ipc-sandbox merge-sync multilib-strict network-sandbox news parallel-fetch pid-sandbox preserve-libs protect-owned qa-unresolved-soname-deps sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox usersync xattr" FFLAGS="-O2 -pipe" GENTOO_MIRRORS="https://ftp.halifax.rwth-aachen.de/gentoo/ http://ftp-stud.fht-esslingen.de/pub/Mirrors/gentoo/" LANG="de_DE.utf8" LDFLAGS="-Wl,-O1 -Wl,--as-needed" MAKEOPTS="-s -j3 -l4" PKGDIR="/var/cache/binpkgs" PORTAGE_COMPRESS="" PORTAGE_CONFIGROOT="/" PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --omit-dir-times --compress --force --whole-file --delete --stats --human-readable --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages --exclude=/.git" PORTAGE_TMPDIR="/var/tmp" USE="X a52 aac acl acpi activities alsa amd64 berkdb branding bzip2 cairo caps cdda cdinstall cdr cjk cli crypt cups dbus declarative djvu dri dssi dts dvd dvdr emboss encode exif ffmpeg fftw fish-completion flac fortran gdbm gif gmp gnutls iconv icu idn inotify ipv6 jack jackmidi jpeg jpeg2k kde kipi kwallet ladspa lapack latex lcms libnotify libsamplerate libtirpc lzma mad mng modplug mp3 mp4 mpeg mtp multilib musepack musicbrainz ncurses nls nptl offensive ogg opengl openmp opus osc pam pango pcre pdf phonon plasma png policykit ppds pulseaudio qml qt5 rar readline samba sasl seccomp semantic-desktop sid slang sndfile speex spell split-usr ssl startup-notification svg systemd taglib tcpd theora threads tiff timidity truetype udev udisks unicode upower usb v4l vaapi vdpau vorbis vpx wayland widgets x264 xattr xcb xml xmp xv xvid zeroconf zlib zsh-completion" ABI_X86="64" ADA_TARGET="gnat_2018" ALSA_CARDS="ice1724 hda-intel usb-audio" APACHE2_MODULES="authn_core authz_core socache_shmcb unixd actions alias auth_basic authn_alias authn_anon authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache cgi cgid dav dav_fs dav_lock deflate dir disk_cache env expires ext_filter file_cache filter headers include info log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling status unique_id userdir usertrack vhost_alias" CALLIGRA_FEATURES="karbon sheets words" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" CPU_FLAGS_X86="mmx mmxext sse sse2 3dnow 3dnowext mmxext sse3" ELIBC="glibc" GPSD_PROTOCOLS="ashtech aivdm earthmate evermore fv18 garmin garmintxt gpsclock greis isync itrax mtk3301 nmea ntrip navcom oceanserver oldstyle oncore rtcm104v2 rtcm104v3 sirf skytraq superstar2 timing tsip tripmate tnt ublox ubx" GRUB_PLATFORMS="pc" INPUT_DEVICES="libinput" KERNEL="linux" L10N="en-US en en-GB de" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LIBREOFFICE_EXTENSIONS="presenter-console presenter-minimizer" OFFICE_IMPLEMENTATION="libreoffice" PHP_TARGETS="php7-2 php7-3" POSTGRES_TARGETS="postgres10 postgres11" PYTHON_SINGLE_TARGET="python3_7" PYTHON_TARGETS="python3_7" RUBY_TARGETS="ruby25" USERLAND="GNU" VIDEO_CARDS="radeon r600" XTABLES_ADDONS="quota2 psd pknock lscan length2 ipv4options ipset ipp2p iface geoip fuzzy condition tee tarpit sysrq steal rawnat logmark ipmark dhcpmac delude chaos account" Unset: CC, CPPFLAGS, CTARGET, CXX, INSTALL_MASK, LC_ALL, LINGUAS, PORTAGE_BINHOST, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS ================================================================= Package Settings ================================================================= sys-apps/systemd-245.5::gentoo was built with the following: USE="acl curl gcrypt hwdb idn importd kmod lz4 lzma pam pcre (policykit) resolvconf seccomp (split-usr) sysv-utils -apparmor -audit -build -cgroup-hybrid -cryptsetup -dns-over-tls -elfutils -gnuefi -homed -http -nat -pkcs11 -pwquality -qrcode -repart (-selinux) -static-libs -test -vanilla -xkb" ABI_X86="32 (64) (-x32)" FEATURES="unmerge-logs strict unknown-features-warn ipc-sandbox xattr userpriv binpkg-dostrip assume-digests distlocks merge-sync multilib-strict network-sandbox sandbox pid-sandbox sfperms userfetch binpkg-docompress ebuild-locks protect-owned preserve-libs usersync fixlafiles config-protect-if-modified binpkg-logs qa-unresolved-soname-deps usersandbox parallel-fetch news unmerge-orphans"
Typically, this is caused by strange characters in your username or some other data in /etc/passwd.
My username contains only ASCII characters. Regardless (and I should have mentioned this initially, but forgot): login fails for root, too. The only way I could get access to a somewhat normally running system was by setting systemd.unit=rescue.target on the kernel command line via GRUB (rd.break and chroot of course also worked).
Hmm... well I am unable to reproduce this problem, so I assume there is *something* odd about your NSS or PAM config. Also, are you able to reproduce the issue with systemd-246?
Another thing I forgot to mention, just for completeness: logging in with SDDM also fails (which is how I noticed this). (In reply to Mike Gilbert from comment #3) > Hmm... well I am unable to reproduce this problem, so I assume there is > *something* odd about your NSS or PAM config. I wouldn't know what, I just use the defaults: # qfile -o /etc/pam.d/* # qcheck $(qfile /etc/pam.d/* /etc/nsswitch.conf | cut -d: -f1 | sort -u) Checking app-admin/sudo ... MD5-DIGEST: /etc/sudoers * 200 out of 201 files are good Checking dev-libs/cyrus-sasl ... * 141 out of 141 files are good Checking kde-plasma/kscreenlocker ... * 297 out of 297 files are good Checking net-fs/samba ... * 518 out of 518 files are good Checking net-mail/mailbase ... * 20 out of 20 files are good Checking net-misc/openssh ... MD5-DIGEST: /etc/ssh/sshd_config * 71 out of 72 files are good Checking net-print/cups ... * 485 out of 485 files are good Checking sys-apps/kbd ... * 793 out of 793 files are good Checking sys-apps/shadow ... * 644 out of 644 files are good Checking sys-apps/systemd ... MD5-DIGEST: /etc/systemd/system.conf MD5-DIGEST: /etc/systemd/logind.conf * 1805 out of 1807 files are good Checking sys-apps/util-linux ... * 546 out of 546 files are good Checking sys-auth/pambase ... * 11 out of 11 files are good Checking sys-auth/polkit ... * 145 out of 145 files are good Checking sys-libs/glibc ... MTIME: /etc/nsswitch.conf MD5-DIGEST: /etc/locale.gen * 2547 out of 2549 files are good Checking x11-misc/sddm ... * 223 out of 223 files are good I suspect only the two modified systemd configuration files might be relevant, but I only set the following: # grep "^[^#].*" systemd/{system.conf,logind.conf} systemd/system.conf:[Manager] systemd/system.conf:DefaultCPUAccounting=yes systemd/system.conf:DefaultIOAccounting=yes systemd/logind.conf:[Login] systemd/logind.conf:KillUserProcesses=yes (I tried without KillUserProcesses and it didn't help.) > Also, are you able to reproduce the issue with systemd-246? Yes. With systemd-userdbd.service running: % su Passwort: ^C % su Passwort: <nothing happens> With the journal showing only: Aug 05 21:50:45 thetick su[779]: Successful su for root by marcec Aug 05 21:50:45 thetick su[779]: + /dev/pts/2 marcec:root Aug 05 21:50:59 thetick su[789]: Successful su for root by marcec Aug 05 21:50:59 thetick su[789]: + /dev/pts/2 marcec:root But I never actually get a shell. (Logging in to a TTY also fails, but I decided to try su for variety.) As soon as I disable systemd-userdbd.socket or mask systemd-userdbd.service, I can log in normally again. FTR: userdbctl also hangs with systemd-userdbd running, but works otherwise.
> FTR: userdbctl also hangs with systemd-userdbd running, but works otherwise. Could you strace userdbctl to see what it is doing when it hangs?
It might also be worth enabling debug logging in systemd-userdbd by adding Environment=SYSTEMD_LOG_LEVEL=debug to systemd-userdbd.service.
(In reply to Mike Gilbert from comment #5) > > FTR: userdbctl also hangs with systemd-userdbd running, but works otherwise. > > Could you strace userdbctl to see what it is doing when it hangs? Sure, I'll attach it. (In reply to Mike Gilbert from comment #6) > It might also be worth enabling debug logging in systemd-userdbd by adding > Environment=SYSTEMD_LOG_LEVEL=debug to systemd-userdbd.service. Right, that shows, when trying to su: # journalctl -u systemd-userdbd.service -f -- Logs begin at Tue 2020-06-23 17:07:20 CEST. -- Aug 05 23:20:46 thetick systemd-userdbd[1260]: Successfully forked off '(sd-worker)' as PID 1261. Aug 05 23:20:46 thetick [1261]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:20:46 thetick systemd-userdbd[1260]: Successfully forked off '(sd-worker)' as PID 1262. Aug 05 23:20:46 thetick systemd-userdbd[1260]: Successfully forked off '(sd-worker)' as PID 1263. Aug 05 23:20:46 thetick systemd[1]: Started User Database Manager. Aug 05 23:20:46 thetick [1262]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:20:46 thetick [1263]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:20:46 thetick systemd-userwork[1261]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:20:46 thetick systemd-userwork[1262]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:20:46 thetick systemd-userwork[1263]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:21:13 thetick systemd-userwork[1261]: varlink-5: varlink: setting state idle-server Aug 05 23:21:13 thetick systemd-userwork[1261]: varlink-5: New incoming message: {"method":"io.systemd.UserDatabase.GetUserRecord","parameters":{"userName":"root","service":"io.systemd.Multiplexer"}} Aug 05 23:21:13 thetick systemd-userwork[1261]: varlink-5: varlink: changing state idle-server → processing-method Aug 05 23:21:13 thetick systemd-userwork[1261]: n/a: varlink: setting state idle-client Aug 05 23:21:13 thetick systemd-userwork[1261]: /run/systemd/userdb/io.systemd.DynamicUser: Sending message: {"method":"io.systemd.UserDatabase.GetUserRecord","parameters":{"userName":"root","service":"io.systemd.DynamicUser"}} Aug 05 23:21:13 thetick systemd-userwork[1261]: /run/systemd/userdb/io.systemd.DynamicUser: varlink: changing state idle-client → awaiting-reply Aug 05 23:21:13 thetick systemd-userwork[1261]: /run/systemd/userdb/io.systemd.DynamicUser: New incoming message: {"error":"io.systemd.UserDatabase.NoRecordFound","parameters":{}} Aug 05 23:21:13 thetick systemd-userwork[1261]: /run/systemd/userdb/io.systemd.DynamicUser: varlink: changing state awaiting-reply → processing-reply Aug 05 23:21:13 thetick systemd-userwork[1261]: Got lookup error: io.systemd.UserDatabase.NoRecordFound Aug 05 23:21:13 thetick systemd-userwork[1261]: /run/systemd/userdb/io.systemd.DynamicUser: varlink: changing state processing-reply → idle-client Aug 05 23:21:13 thetick systemd-userwork[1261]: [458B blob data] Aug 05 23:21:13 thetick systemd-userwork[1261]: varlink-5: varlink: changing state processing-method → processed-method Aug 05 23:21:13 thetick systemd-userwork[1261]: varlink-5: varlink: changing state processed-method → idle-server Aug 05 23:21:13 thetick systemd-userwork[1261]: varlink-5: Got POLLHUP from socket. Aug 05 23:21:13 thetick systemd-userwork[1261]: varlink-5: varlink: changing state idle-server → pending-disconnect Aug 05 23:21:13 thetick systemd-userwork[1261]: varlink-5: varlink: changing state pending-disconnect → processing-disconnect Aug 05 23:21:13 thetick systemd-userwork[1261]: varlink-5: varlink: changing state processing-disconnect → disconnected Aug 05 23:21:13 thetick systemd-userwork[1261]: Connection terminated. And later on trying "userdbctl user root" twice (the second of which corresponds to the log I'll attach): # journalctl -u systemd-userdbd.service -f -- Logs begin at Tue 2020-06-23 17:07:20 CEST. -- Aug 05 23:24:25 thetick systemd-userdbd[1418]: Successfully forked off '(sd-worker)' as PID 1419. Aug 05 23:24:25 thetick [1419]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:24:25 thetick systemd-userdbd[1418]: Successfully forked off '(sd-worker)' as PID 1420. Aug 05 23:24:25 thetick systemd-userdbd[1418]: Successfully forked off '(sd-worker)' as PID 1421. Aug 05 23:24:25 thetick [1420]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:24:25 thetick systemd[1]: Started User Database Manager. Aug 05 23:24:25 thetick [1421]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:24:25 thetick systemd-userwork[1419]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:24:25 thetick systemd-userwork[1420]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:24:25 thetick systemd-userwork[1421]: PR_SET_MM_ARG_START failed: Operation not permitted Aug 05 23:24:33 thetick systemd-userwork[1419]: varlink-5: varlink: setting state idle-server Aug 05 23:24:33 thetick systemd-userwork[1419]: varlink-5: New incoming message: {"method":"io.systemd.UserDatabase.GetUserRecord","parameters":{"userName":"root","service":"io.systemd.Multiplexer"}} Aug 05 23:24:33 thetick systemd-userwork[1419]: varlink-5: varlink: changing state idle-server → processing-method Aug 05 23:24:33 thetick systemd-userwork[1419]: n/a: varlink: setting state idle-client Aug 05 23:24:33 thetick systemd-userwork[1419]: /run/systemd/userdb/io.systemd.DynamicUser: Sending message: {"method":"io.systemd.UserDatabase.GetUserRecord","parameters":{"userName":"root","service":"io.systemd.DynamicUser"}} Aug 05 23:24:33 thetick systemd-userwork[1419]: /run/systemd/userdb/io.systemd.DynamicUser: varlink: changing state idle-client → awaiting-reply Aug 05 23:24:33 thetick systemd-userwork[1419]: /run/systemd/userdb/io.systemd.DynamicUser: New incoming message: {"error":"io.systemd.UserDatabase.NoRecordFound","parameters":{}} Aug 05 23:24:33 thetick systemd-userwork[1419]: /run/systemd/userdb/io.systemd.DynamicUser: varlink: changing state awaiting-reply → processing-reply Aug 05 23:24:33 thetick systemd-userwork[1419]: Got lookup error: io.systemd.UserDatabase.NoRecordFound Aug 05 23:24:33 thetick systemd-userwork[1419]: /run/systemd/userdb/io.systemd.DynamicUser: varlink: changing state processing-reply → idle-client Aug 05 23:24:33 thetick systemd-userwork[1419]: [458B blob data] Aug 05 23:24:33 thetick systemd-userwork[1419]: varlink-5: varlink: changing state processing-method → processed-method Aug 05 23:24:33 thetick systemd-userwork[1419]: varlink-5: varlink: changing state processed-method → idle-server Aug 05 23:24:33 thetick systemd-userwork[1419]: varlink-5: Got POLLHUP from socket. Aug 05 23:24:33 thetick systemd-userwork[1419]: varlink-5: varlink: changing state idle-server → pending-disconnect Aug 05 23:24:33 thetick systemd-userwork[1419]: varlink-5: varlink: changing state pending-disconnect → processing-disconnect Aug 05 23:24:33 thetick systemd-userwork[1419]: varlink-5: varlink: changing state processing-disconnect → disconnected Aug 05 23:24:33 thetick systemd-userwork[1419]: Connection terminated. Aug 05 23:27:26 thetick systemd-userwork[1419]: varlink-5: varlink: setting state idle-server Aug 05 23:27:26 thetick systemd-userwork[1419]: varlink-5: New incoming message: {"method":"io.systemd.UserDatabase.GetUserRecord","parameters":{"userName":"root","service":"io.systemd.Multiplexer"}} Aug 05 23:27:26 thetick systemd-userwork[1419]: varlink-5: varlink: changing state idle-server → processing-method Aug 05 23:27:26 thetick systemd-userwork[1419]: n/a: varlink: setting state idle-client Aug 05 23:27:26 thetick systemd-userwork[1419]: /run/systemd/userdb/io.systemd.DynamicUser: Sending message: {"method":"io.systemd.UserDatabase.GetUserRecord","parameters":{"userName":"root","service":"io.systemd.DynamicUser"}} Aug 05 23:27:26 thetick systemd-userwork[1419]: /run/systemd/userdb/io.systemd.DynamicUser: varlink: changing state idle-client → awaiting-reply Aug 05 23:27:26 thetick systemd-userwork[1419]: /run/systemd/userdb/io.systemd.DynamicUser: New incoming message: {"error":"io.systemd.UserDatabase.NoRecordFound","parameters":{}} Aug 05 23:27:26 thetick systemd-userwork[1419]: /run/systemd/userdb/io.systemd.DynamicUser: varlink: changing state awaiting-reply → processing-reply Aug 05 23:27:26 thetick systemd-userwork[1419]: Got lookup error: io.systemd.UserDatabase.NoRecordFound Aug 05 23:27:26 thetick systemd-userwork[1419]: /run/systemd/userdb/io.systemd.DynamicUser: varlink: changing state processing-reply → idle-client Aug 05 23:27:26 thetick systemd-userwork[1419]: [458B blob data] Aug 05 23:27:26 thetick systemd-userwork[1419]: varlink-5: varlink: changing state processing-method → processed-method Aug 05 23:27:26 thetick systemd-userwork[1419]: varlink-5: varlink: changing state processed-method → idle-server Aug 05 23:27:26 thetick systemd-userwork[1419]: varlink-5: Got POLLHUP from socket. Aug 05 23:27:26 thetick systemd-userwork[1419]: varlink-5: varlink: changing state idle-server → pending-disconnect Aug 05 23:27:26 thetick systemd-userwork[1419]: varlink-5: varlink: changing state pending-disconnect → processing-disconnect Aug 05 23:27:26 thetick systemd-userwork[1419]: varlink-5: varlink: changing state processing-disconnect → disconnected Aug 05 23:27:26 thetick systemd-userwork[1419]: Connection terminated.
Created attachment 653312 [details] Output of "strace userdbctl user root" with systemd-userdbd running. Here's the strace output. It looks like userdbctl actually got a response from the second recvfrom(), but is waiting for a response from systemd-userdbd, which it seems has closed the connection in the meantime.
This entry in your journal seems strange/broken: > systemd-userwork[1261]: [458B blob data] When I run "userdbctl user root" on my system, I see a message indicating it is sending a JSON message at that point. > systemd-userwork[1381555]: varlink-5: Sending message: {"parameters":{"record":{"userName":"root","uid":0,"gid":0,"homeDirectory":"/root","shell":"/bin/bash","privileged":{"hashedPassword":["REDACTED"]},"passwordChangeNow":false,"lastPasswordChangeUSec":1310947200000000,"status":{"4e39f1235b04c6398c7a5eaa0000000b":{"service":"io.systemd.NameServiceSwitch"}}},"incomplete":false}}
Created attachment 653314 [details] journal output Here's my full journal output for reference. I would suggest you open an issue upstream if you are unable to figure out what's up on your system.
(In reply to Mike Gilbert from comment #10) > Created attachment 653314 [details] > journal output > > Here's my full journal output for reference. > > I would suggest you open an issue upstream if you are unable to figure out > what's up on your system. Huh, is the "REDACTED" as-is in the journal output, or did you edit it? I changed the journalctl output to "cat" and see the full message there, and it turns out the reason it's binary is because it includes the full hashed password. I decided to run "file /etc/shadow", which said that the file was ISO-8859 encoded. That lead me to the "fix": I reentered the password to root (i.e., it didn't change), which however changed the hashed password in /etc/shadow. After that "userdbctl user root" ran successfully. I did the same for my normal user, which also seems to have fixed things. /etc/shadow is now ASCII encoded, according to file. (The journal entry still contains the full hashed password, though.) So my theory is as follows: - The hash algorithm used by shadow (or whatever is responsible) was changed in the last decade or so. - systemd-userdbd can't deal with passwords hashed using the old algorithm.
And before I forget: thanks for the help!
Yes, I removed the hash from my journal output. If you have a copy of the original shadow file, it would be interesting to see exactly what bytes were stored there. I’m not aware of a password hash scheme that uses non ascii characters.
OK, here's the first few characters of the hashed root password, which includes the two problematic ones. Output from cat(1): $1$h�k�F/ The corresponding bytes as output by "hexdump -c" $ 1 $ h 350 k 372 F / I'm not sure what to make of those numbers, though it seems they must be octal, or else they don't fit in a byte. That would make them decimal 232 and 250 (which match the hexadecimal place-holders used by less(1)), which is outside of the ASCII range. Grepping for those in the ISO-8859 man pages does not result in unprintable output, though.
Nicely found. The $1$ indicates that this is an MD5-hashed password. The characters between the second and third dollar sign ($) are the salt value. https://www.man7.org/linux/man-pages/man3/crypt.3.html As a test I updated /etc/pam.d/system-auth on my system to generate MD5 hashes. The salt values generated always seem to consist of ASCII characters. Perhaps some older version of glibc generated salt values that contain arbitrary binary data? I'm not finding anything about this on Google though. systemd probably assumes /etc/shadow will contain ASCII or UTF-8 data. If we can demonstrate some legitimate purpose for binary data in this file, we might be able to convince them to update the code that processes it. It might be worth creating an issue upstream in any case.
I opened an upstream report, see $URL. I had written more, but accidentally lost it when trying to upload the userdbctl.log file, so it's more concise than it was originally.
Upstream closed my bug via https://github.com/systemd/systemd/pull/16911/, but I'm unable to tell what exactly systemd-userdbd does now. All I can tell from the commit messages is that the lower levels check more rigorously for valid UTF-8 now, but not what happens when that check fails. Does it just abort the login now instead of hanging?
If I understand correctly, if the password hash contains invalid UTF-8 characters, it is simply dropped from the userdbd JSON response. I would expect authentication via pam_unix to work fine since it doesn't actually use userdbd. I would also expect the pam_systemd session handler to work since it doesn't actually need the password hash. Anyway, I'm not planning to backport these changes since I suspect very few people will run into this. We'll pick up the fix when it hits a release.
