pam_systemd fails to create session for root if pam_systemd_home is used for account

[tomty89]

systemd version the issue has been seen with

246.6

Used distribution

Arch Linux ARM (Raspberry Pi 4)

Linux kernel version used (uname -a)

Linux alarmpi 5.4.69-1-ARCH #1 SMP PREEMPT Fri Oct 2 18:33:37 UTC 2020 armv7l GNU/Linux

CPU architecture issue was seen on

armv7l

Expected behaviour you didn't see

root login works fine; session can be created; no stalling or quitting

Unexpected behaviour you saw

• session creation fails for root with the error of Input/output error
• login either stalls and "succeed" without a (logind) session created, or fails and quits entirely after stalling
• login works fine for non-root user
• such problem is not observed on Arch Linux (x86_64), even though the pam confs are identical (unless I missed something)
• not yet tested with aarch64 mainline kernel
• the problem is observed by me on tty login, but I saw recent report with similar error and workaround for ssh login on Arch Linux ARM forum

Steps to reproduce the problem

Note: systemd-home is not enabled/started
https://github.com/archlinux/svntogit-packages/blob/2d5af94ae55a5c98837ce9631f331ad2aad32bb3/trunk/system-login
https://github.com/archlinux/svntogit-packages/blob/2d5af94ae55a5c98837ce9631f331ad2aad32bb3/trunk/system-auth
(commenting the pam_systemd_home:account line seem to avoid the the problem)

[tomty89]

Forgot to mention that it does NOT always fail, but often fails.

[poettering]

Please provide logs for this

[helllamer]

Have same problem on raspberry-pi-2 after update yesterday on Archlinux ARM.
Need at least ~2 to 6 tries, to login via ssh once.

# pacman -Qs systemd
local/netctl 1.23-1
    Profile based systemd network management
local/systemd 246.6-1.1
    system and service manager
local/systemd-libs 246.6-1.1
    systemd client libraries
local/systemd-sysvcompat 246.6-1.1
    sysvinit compat for systemd

# pacman -Qs openssh
local/openssh 8.4p1-1
    Premier connectivity tool for remote login with the SSH protocol

# uname -a
Linux tvpi 5.4.72-1-ARCH #1 SMP PREEMPT Mon Oct 19 15:33:45 UTC 2020 armv7l GNU/Linux

Server logs:

окт 26 12:25:58 tvpi sshd[482]: debug1: Forked child 658.
окт 26 12:25:58 tvpi sshd[658]: debug1: Set /proc/self/oom_score_adj to 0
окт 26 12:25:58 tvpi sshd[658]: debug1: rexec start in 4 out 4 newsock 4 pipe 6 sock 7
окт 26 12:25:58 tvpi sshd[658]: debug1: inetd sockets after dupping: 4, 4
окт 26 12:25:58 tvpi sshd[658]: Connection from 192.168.0.192 port 60160 on 192.168.0.1 port 22 rdomain ""
окт 26 12:25:58 tvpi sshd[658]: debug1: Local version string SSH-2.0-OpenSSH_8.4
окт 26 12:25:58 tvpi sshd[658]: debug1: Remote protocol version 2.0, remote software version OpenSSH_8.4
окт 26 12:25:58 tvpi sshd[658]: debug1: match: OpenSSH_8.4 pat OpenSSH* compat 0x04000000
окт 26 12:25:58 tvpi sshd[658]: debug1: permanently_set_uid: 65534/65534 [preauth]
окт 26 12:25:58 tvpi sshd[658]: debug1: list_hostkey_types: ssh-ed25519 [preauth]
окт 26 12:25:58 tvpi sshd[658]: debug1: SSH2_MSG_KEXINIT sent [preauth]
окт 26 12:25:58 tvpi sshd[658]: debug1: SSH2_MSG_KEXINIT received [preauth]
окт 26 12:25:58 tvpi sshd[658]: debug1: kex: algorithm: curve25519-sha256@libssh.org [preauth]
окт 26 12:25:58 tvpi sshd[658]: debug1: kex: host key algorithm: ssh-ed25519 [preauth]
окт 26 12:25:58 tvpi sshd[658]: debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: zlib@openssh.com [preauth]
окт 26 12:25:58 tvpi sshd[658]: debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: zlib@openssh.com [preauth]
окт 26 12:25:58 tvpi sshd[658]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: rekey out after 134217728 blocks [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: Sending SSH2_MSG_EXT_INFO [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: SSH2_MSG_NEWKEYS received [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: rekey in after 134217728 blocks [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: KEX done [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: userauth-request for user root service ssh-connection method none [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: attempt 0 failures 0 [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: PAM: initializing for "root"
окт 26 12:25:59 tvpi sshd[658]: debug1: PAM: setting PAM_RHOST to "192.168.0.192"
окт 26 12:25:59 tvpi sshd[658]: debug1: PAM: setting PAM_TTY to "ssh"
окт 26 12:25:59 tvpi sshd[658]: debug1: userauth-request for user root service ssh-connection method publickey [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: attempt 1 failures 0 [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: userauth_pubkey: test pkalg ssh-ed25519 pkblob ED25519 SHA256:Fxccg/XL...........................................a4r/EI [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: temporarily_use_uid: 0/0 (e=0/0)
окт 26 12:25:59 tvpi sshd[658]: debug1: trying public key file /root/.ssh/authorized_keys
окт 26 12:25:59 tvpi sshd[658]: debug1: fd 5 clearing O_NONBLOCK
окт 26 12:25:59 tvpi sshd[658]: debug1: /root/.ssh/authorized_keys:1: matching key found: ED25519 SHA256:Fxccg/XL...............................................a4r/EI
окт 26 12:25:59 tvpi sshd[658]: debug1: /root/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
окт 26 12:25:59 tvpi sshd[658]: Accepted key ED25519 SHA256:Fxccg/XL.......................................a4r/EI found at /root/.ssh/authorized_keys:1
окт 26 12:25:59 tvpi sshd[658]: debug1: restore_uid: 0/0
окт 26 12:25:59 tvpi sshd[658]: Postponed publickey for root from 192.168.0.192 port 60160 ssh2 [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: userauth-request for user root service ssh-connection method publickey [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: attempt 2 failures 0 [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: temporarily_use_uid: 0/0 (e=0/0)
окт 26 12:25:59 tvpi sshd[658]: debug1: trying public key file /root/.ssh/authorized_keys
окт 26 12:25:59 tvpi sshd[658]: debug1: fd 5 clearing O_NONBLOCK
окт 26 12:25:59 tvpi sshd[658]: debug1: /root/.ssh/authorized_keys:1: matching key found: ED25519 SHA256:Fxccg/XL.............................................a4r/EI
окт 26 12:25:59 tvpi sshd[658]: debug1: /root/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
окт 26 12:25:59 tvpi sshd[658]: Accepted key ED25519 SHA256:Fxccg/XL....................................a4r/EI found at /root/.ssh/authorized_keys:1
окт 26 12:25:59 tvpi sshd[658]: debug1: restore_uid: 0/0
окт 26 12:25:59 tvpi sshd[658]: debug1: auth_activate_options: setting new authentication options
окт 26 12:25:59 tvpi audit[658]: USER_ACCT pid=658 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_permit,pam_time acct="root" exe="/usr/bin/ss>
окт 26 12:25:59 tvpi sshd[658]: debug1: do_pam_account: called
окт 26 12:25:59 tvpi sshd[658]: Accepted publickey for root from 192.168.0.192 port 60160 ssh2: ED25519 SHA256:Fxccg/XL.............................................a4r/EI
окт 26 12:25:59 tvpi sshd[658]: debug1: monitor_child_preauth: root has been authenticated by privileged process
окт 26 12:25:59 tvpi sshd[658]: debug1: auth_activate_options: setting new authentication options [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: Enabling compression at level 6. [preauth]
окт 26 12:25:59 tvpi sshd[658]: debug1: monitor_read_log: child log fd closed
окт 26 12:25:59 tvpi sshd[658]: debug1: PAM: establishing credentials
окт 26 12:25:59 tvpi sshd[658]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)
окт 26 12:25:59 tvpi sshd[658]: pam_systemd(sshd:session): Failed to create session: Input/output error
окт 26 12:25:59 tvpi audit[658]: CRED_ACQ pid=658 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock acct="r>
окт 26 12:25:59 tvpi kernel: audit: type=1101 audit(1603704359.461:207): pid=658 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_permit,pam_tim>
окт 26 12:25:59 tvpi kernel: audit: type=1103 audit(1603704359.481:208): pid=658 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_perm>
окт 26 12:25:59 tvpi kernel: audit: type=1006 audit(1603704359.481:209): pid=658 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=31 res=1

------- Part 2: after 25 seconds of silence. 15 seconds ago, SSH-client was killed manually -------

окт 26 12:26:24 tvpi audit[658]: USER_START pid=658 uid=0 auid=0 ses=31 msg='op=PAM:session_open grantors=pam_loginuid,pam_keyinit,pam_limits,pam_unix,pam_permit,pam_mail,pam_env acct="root" exe="/usr/b>
окт 26 12:26:24 tvpi sshd[658]: debug1: rekey in after 134217728 blocks
окт 26 12:26:24 tvpi sshd[658]: debug1: rekey out after 134217728 blocks
окт 26 12:26:24 tvpi sshd[658]: debug1: ssh_packet_set_postauth: called
окт 26 12:26:24 tvpi sshd[658]: debug1: Enabling compression at level 6.
окт 26 12:26:24 tvpi sshd[658]: debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
окт 26 12:26:24 tvpi sshd[658]: debug1: Entering interactive session for SSH2.
окт 26 12:26:24 tvpi sshd[658]: debug1: server_init_dispatch
окт 26 12:26:24 tvpi sshd[658]: debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
окт 26 12:26:24 tvpi sshd[658]: debug1: input_session_request
окт 26 12:26:24 tvpi sshd[658]: debug1: channel 0: new [server-session]
окт 26 12:26:24 tvpi sshd[658]: debug1: session_new: session 0
окт 26 12:26:24 tvpi sshd[658]: debug1: session_open: channel 0
окт 26 12:26:24 tvpi sshd[658]: debug1: session_open: session 0: link with channel 0
окт 26 12:26:24 tvpi sshd[658]: debug1: server_input_channel_open: confirm session
окт 26 12:26:24 tvpi sshd[658]: debug1: server_input_global_request: rtype no-more-sessions@openssh.com want_reply 0
окт 26 12:26:24 tvpi sshd[658]: Received disconnect from 192.168.0.192 port 60160:11: disconnected by user
окт 26 12:26:24 tvpi sshd[658]: Disconnected from user root 192.168.0.192 port 60160
окт 26 12:26:24 tvpi sshd[658]: debug1: do_cleanup
окт 26 12:26:24 tvpi sshd[658]: debug1: PAM: cleanup
окт 26 12:26:24 tvpi sshd[658]: debug1: PAM: closing session
окт 26 12:26:24 tvpi sshd[658]: pam_unix(sshd:session): session closed for user root
окт 26 12:26:24 tvpi sshd[658]: debug1: PAM: deleting credentials
окт 26 12:26:24 tvpi sshd[482]: debug1: main_sigchld_handler: Child exited
окт 26 12:26:24 tvpi audit[658]: USER_END pid=658 uid=0 auid=0 ses=31 msg='op=PAM:session_close grantors=pam_loginuid,pam_keyinit,pam_limits,pam_unix,pam_permit,pam_mail,pam_env acct="root" exe="/usr/bi>
окт 26 12:26:24 tvpi kernel: audit: type=1105 audit(1603704384.521:222): pid=658 uid=0 auid=0 ses=31 msg='op=PAM:session_open grantors=pam_loginuid,pam_keyinit,pam_limits,pam_unix,pam_permit,pam_mail,pa>
окт 26 12:26:24 tvpi kernel: audit: type=1106 audit(1603704384.521:223): pid=658 uid=0 auid=0 ses=31 msg='op=PAM:session_close grantors=pam_loginuid,pam_keyinit,pam_limits,pam_unix,pam_permit,pam_mail,p>
окт 26 12:26:24 tvpi audit[658]: CRED_DISP pid=658 uid=0 auid=0 ses=31 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock acct="root" exe="/usr/bin/sshd" hostname=192.1>
окт 26 12:26:24 tvpi kernel: audit: type=1104 audit(1603704384.521:224): pid=658 uid=0 auid=0 ses=31 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock acct="root" exe=>
окт 26 12:26:29 tvpi audit[660]: USER_START pid=660 uid=0 auid=0 ses=32 msg='op=PAM:session_open grantors=pam_loginuid,pam_keyinit,pam_limits,pam_unix,pam_permit,pam_mail,pam_env acct="root" exe="/usr/b>

In some cases, have 100% CPU on hanged sshd for at least 10 minutes (if dont kill ssh-client for a long time):

# top
  589 root      20   0   14732   7148   6260 R  99,9   1,4   4:06.15 sshd                                                                                                                     
  620 root      20   0   14732   7280   6392 R  100.0   1,5   1:13.87 sshd

Loginctl shows nothing about hanged ssh-sessions, only current normal and active user session:

# loginctl 
SESSION UID USER SEAT TTY
     23   0 root         

1 sessions listed.

ssh-client debug logs, if needed:

$ ssh root@tvpi -v
OpenSSH_8.4p1, OpenSSL 1.1.1h  22 Sep 2020
debug1: Reading configuration data /home/user/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Connecting to tvpi [192.168.0.1] port 22.
debug1: Connection established.
debug1: identity file /home/user/.ssh/id_rsa type 0
debug1: identity file /home/user/.ssh/id_rsa-cert type -1
debug1: identity file /home/user/.ssh/id_dsa type -1
debug1: identity file /home/user/.ssh/id_dsa-cert type -1
debug1: identity file /home/user/.ssh/id_ecdsa type -1
debug1: identity file /home/user/.ssh/id_ecdsa-cert type -1
debug1: identity file /home/user/.ssh/id_ecdsa_sk type -1
debug1: identity file /home/user/.ssh/id_ecdsa_sk-cert type -1
debug1: identity file /home/user/.ssh/id_ed25519 type 3
debug1: identity file /home/user/.ssh/id_ed25519-cert type -1
debug1: identity file /home/user/.ssh/id_ed25519_sk type -1
debug1: identity file /home/user/.ssh/id_ed25519_sk-cert type -1
debug1: identity file /home/user/.ssh/id_xmss type -1
debug1: identity file /home/user/.ssh/id_xmss-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_8.4
debug1: Remote protocol version 2.0, remote software version OpenSSH_8.4
debug1: match: OpenSSH_8.4 pat OpenSSH* compat 0x04000000
debug1: Authenticating to tvpi:22 as 'root'
debug1: SSH2_MSG_KEXINIT sent
debug1: SSH2_MSG_KEXINIT received
debug1: kex: algorithm: curve25519-sha256@libssh.org
debug1: kex: host key algorithm: ssh-ed25519
debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: zlib@openssh.com
debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: zlib@openssh.com
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug1: Server host key: ssh-ed25519 SHA256:pG...............................28
debug1: Host 'tvpi' is known and matches the ED25519 host key.
debug1: Found key in /home/user/.ssh/known_hosts:219
debug1: rekey out after 134217728 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug1: SSH2_MSG_NEWKEYS received
debug1: rekey in after 134217728 blocks
debug1: Will attempt key: /home/user/.ssh/id_ed25519 ED25519 SHA256:Fxccg/XL.................a4r/EI agent
debug1: Will attempt key: /home/user/.ssh/id_rsa RSA SHA256:c7s...................................KQI agent
debug1: Will attempt key: /home/user/.ssh/id_dsa 
debug1: Will attempt key: /home/user/.ssh/id_ecdsa 
debug1: Will attempt key: /home/user/.ssh/id_ecdsa_sk 
debug1: Will attempt key: /home/user/.ssh/id_ed25519_sk 
debug1: Will attempt key: /home/user/.ssh/id_xmss 
debug1: SSH2_MSG_EXT_INFO received
debug1: kex_input_ext_info: server-sig-algs=<ssh-ed25519,sk-ssh-ed25519@openssh.com,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ecdsa-sha2-nistp256@openssh.com,webauthn-sk-ecdsa-sha2-nistp256@openssh.com>
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug1: Authentications that can continue: publickey
debug1: Next authentication method: publickey
debug1: Offering public key: /home/user/.ssh/id_ed25519 ED25519 SHA256:Fxccg/XL................................a4r/EI agent
debug1: Server accepts key: /home/user/.ssh/id_ed25519 ED25519 SHA256:Fxccg/XL...............................a4r/EI agent
debug1: Enabling compression at level 6.
debug1: Authentication succeeded (publickey).
Authenticated to tvpi ([192.168.0.1]:22).
debug1: channel 0: new [client-session]
debug1: Requesting no-more-sessions@openssh.com
debug1: Entering interactive session.
debug1: pledge: network

[hang]

Server's systemd in default configuration, except enabled services/networks and journalctl.conf:

[Journal]
Storage=volatile
Compress=yes
SystemMaxUse=20M

[helllamer]

Also:

commenting the pam_systemd_home:account line seem to avoid the the problem

Same for me. Fix in /etc/pam.d/system-auth by commenting line:
#-account [success=1 default=ignore] pam_systemd_home.so

systemd-homed enabled or disabled, running or not -- not affects the problem.

[helllamer]

Sorry, forgot debug logs for systemd

# systemctl log-level debug

окт 26 13:03:32 tvpi audit[903]: USER_ACCT pid=903 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_permit,pam_time acct="root" exe="/usr/bin/sshd" hostname=192.16>
окт 26 13:03:32 tvpi sshd[903]: Accepted publickey for root from 192.168.0.192 port 60398 ssh2: ED25519 SHA256:Fxccg/XL.........................................a4r/EI
окт 26 13:03:32 tvpi sshd[903]: debug1: monitor_child_preauth: root has been authenticated by privileged process
окт 26 13:03:32 tvpi sshd[903]: debug1: auth_activate_options: setting new authentication options [preauth]
окт 26 13:03:32 tvpi sshd[903]: debug1: Enabling compression at level 6. [preauth]
окт 26 13:03:32 tvpi sshd[903]: debug1: monitor_read_log: child log fd closed
окт 26 13:03:32 tvpi sshd[903]: debug1: PAM: establishing credentials
окт 26 13:03:32 tvpi kernel: kauditd_printk_skb: 1 callbacks suppressed
окт 26 13:03:32 tvpi kernel: audit: type=1101 audit(1603706612.949:378): pid=903 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:accounting grantors=pam_access,pam_permit,pam_time acct="root" exe=">
окт 26 13:03:32 tvpi sshd[903]: pam_unix(sshd:session): session opened for user root(uid=0) by (uid=0)
окт 26 13:03:32 tvpi systemd[1]: n/a: New incoming connection.
окт 26 13:03:32 tvpi systemd[1]: n/a: Connections of user 0: 0 (of 1024 max)
окт 26 13:03:32 tvpi systemd[1]: varlink-21: varlink: setting state idle-server
окт 26 13:03:32 tvpi systemd[1]: varlink-21: New incoming message: {"method":"io.systemd.UserDatabase.GetUserRecord","parameters":{"userName":"root","service":"io.systemd.DynamicUser"}}
окт 26 13:03:32 tvpi systemd[1]: varlink-21: varlink: changing state idle-server → processing-method
окт 26 13:03:32 tvpi systemd[1]: varlink-21: Sending message: {"error":"io.systemd.UserDatabase.NoRecordFound","parameters":{}}
окт 26 13:03:32 tvpi systemd[1]: varlink-21: varlink: changing state processing-method → processed-method
окт 26 13:03:32 tvpi systemd[1]: varlink-21: varlink: changing state processed-method → idle-server
окт 26 13:03:32 tvpi systemd[1]: varlink-21: Got POLLHUP from socket.
окт 26 13:03:32 tvpi sshd[903]: pam_systemd(sshd:session): Failed to create session: Input/output error
окт 26 13:03:32 tvpi systemd[1]: varlink-21: varlink: changing state idle-server → pending-disconnect
окт 26 13:03:32 tvpi systemd[1]: varlink-21: varlink: changing state pending-disconnect → processing-disconnect
окт 26 13:03:32 tvpi systemd[1]: varlink-21: varlink: changing state processing-disconnect → disconnected
окт 26 13:03:32 tvpi audit[903]: CRED_ACQ pid=903 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_faillock acct="root" exe="/usr/bin/>
окт 26 13:03:33 tvpi kernel: audit: type=1103 audit(1603706612.959:379): pid=903 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_shells,pam_faillock,pam_permit,pam_env,pam_fail>
окт 26 13:03:33 tvpi kernel: audit: type=1006 audit(1603706612.959:380): pid=903 uid=0 old-auid=4294967295 auid=0 tty=(none) old-ses=4294967295 ses=56 res=1

[SjonHortensius]

I experience the same issue with systemd 249.7-2 also using archlinuxarm 5.10.83-1-rpi-ARCH #1 SMP Tue Dec 7 15:22:25 UTC 2021 armv7l GNU/Linux on a raspberry pi and it's a pretty terrible experience. It seems systemd hangs until it hits a timeout:

[pid  1352] 08:28:22.849983 openat(AT_FDCWD, "/etc/userdb/root.user", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid  1352] 08:28:22.850186 openat(AT_FDCWD, "/run/userdb/root.user", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid  1352] 08:28:22.850558 openat(AT_FDCWD, "/run/host/userdb/root.user", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid  1352] 08:28:22.850994 openat(AT_FDCWD, "/usr/local/lib/userdb/root.user", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid  1352] 08:28:22.851318 openat(AT_FDCWD, "/usr/lib/userdb/root.user", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid  1352] 08:28:22.851599 openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 7
[pid  1352] 08:28:22.851820 fstat64(7, {st_mode=S_IFREG|0644, st_size=874, ...}) = 0
[pid  1352] 08:28:22.852048 _llseek(7, 0, [0], SEEK_SET) = 0
[pid  1352] 08:28:22.852195 read(7, "root:x:0:0::/root:/bin/bash\nbin:"..., 4096) = 874
[pid  1352] 08:28:22.852428 close(7)    = 0
[pid  1352] 08:28:22.852601 openat(AT_FDCWD, "/etc/shadow", O_RDONLY|O_CLOEXEC) = 7
[pid  1352] 08:28:22.852810 fstat64(7, {st_mode=S_IFREG|0600, st_size=632, ...}) = 0
[pid  1352] 08:28:22.852987 _llseek(7, 0, [0], SEEK_SET) = 0
[pid  1352] 08:28:22.853116 read(7, "root:$6$EesuJmEf6pPFDe93$D8KLr1e"..., 4096) = 632
[pid  1352] 08:28:22.853256 close(7)    = 0
[pid  1352] 08:28:22.853455 close(9)    = 0
[pid  1352] 08:28:22.853608 close(10)   = 0
[pid  1352] 08:28:22.853945 access("/run/systemd/seats/", F_OK) = 0
[pid  1352] 08:28:22.854475 recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="DATA\r\nOK 830d6c811c93b5bef6f3d11"..., iov_len=256}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 58
[pid  1352] 08:28:22.854758 sendmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\0\0\0\0\1\0\0\0m\0\0\0\1\1o\0\25\0\0\0/org/fre"..., iov_len=128}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 128
[pid  1352] 08:28:22.856138 recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\n\0\0\0\1\0\0\0=\0\0\0\6\1s\0\5\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24
[pid  1352] 08:28:22.856444 recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base=":1.14\0\0\0\5\1u\0\1\0\0\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0"..., iov_len=66}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 66
[pid  1352] 08:28:22.856754 recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\4\1\1\n\0\0\0\2\0\0\0\215\0\0\0\1\1o\0\25\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24
[pid  1352] 08:28:22.856986 recvmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="/org/freedesktop/DBus\0\0\0\2\1s\0\24\0\0\0"..., iov_len=146}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 146
[pid  1352] 08:28:22.857262 getpid()    = 1352
[pid  1352] 08:28:22.857384 send(3, "<83>Dec 24 08:28:22 sshd[1352]: "..., 103, MSG_NOSIGNAL) = 103
[pid  1352] 08:28:22.857695 recvmsg(5, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable)
[pid  1352] 08:28:22.857899 ppoll_time64([{fd=5, events=POLLIN}], 1, {tv_sec=24, tv_nsec=996852000}, NULL, 8) = 0 (Timeout)

[pid  1352] 08:28:47.880258 close(5)    = 0
[pid  1352] 08:28:47.881656 getpid()    = 1352
[pid  1352] 08:28:47.881889 send(3, "<87>Dec 24 08:28:47 sshd[1352]: "..., 101, MSG_NOSIGNAL) = 101
[pid  1352] 08:28:47.882231 openat(AT_FDCWD, "/etc/security/pam_env.conf", O_RDONLY|O_LARGEFILE) = 5
[pid  1352] 08:28:47.882495 fstat64(5, {st_mode=S_IFREG|0644, st_size=2971, ...}) = 0
[pid  1352] 08:28:47.882729 read(5, "#\n# This is the configuration fi"..., 4096) = 2971
[pid  1352] 08:28:47.883054 read(5, "", 4096) = 0
[pid  1352] 08:28:47.883252 close(5)    = 0
[pid  1352] 08:28:47.883468 openat(AT_FDCWD, "/etc/environment", O_RDONLY|O_LARGEFILE) = 5
[pid  1352] 08:28:47.883760 fstat64(5, {st_mode=S_IFREG|0644, st_size=97, ...}) = 0
[pid  1352] 08:28:47.884056 read(5, "#\n# This file is parsed by pam_e"..., 4096) = 97
[pid  1352] 08:28:47.884370 read(5, "", 4096) = 0
[pid  1352] 08:28:47.884615 close(5)    = 0
[pid  1352] 08:28:47.884857 openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 5
[pid  1352] 08:28:47.885110 fstat64(5, {st_mode=S_IFREG|0644, st_size=874, ...}) = 0
[pid  1352] 08:28:47.885338 _llseek(5, 0, [0], SEEK_SET) = 0
[pid  1352] 08:28:47.885561 read(5, "root:x:0:0::/root:/bin/bash\nbin:"..., 4096) = 874
[pid  1352] 08:28:47.885790 close(5)    = 0
[pid  1352] 08:28:47.886026 stat64("/root/.pam_environment", 0xbe92b368) = -1 ENOENT (No such file or directory)
[pid  1352] 08:28:47.886273 socket(AF_NETLINK, SOCK_RAW, NETLINK_AUDIT) = 5
[pid  1352] 08:28:47.886495 fcntl64(5, F_SETFD, FD_CLOEXEC) = 0
[pid  1352] 08:28:47.886707 socket(AF_NETLINK, SOCK_RAW|SOCK_CLOEXEC, NETLINK_ROUTE) = 7
[pid  1352] 08:28:47.886906 bind(7, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 0
[pid  1352] 08:28:47.887134 getsockname(7, {sa_family=AF_NETLINK, nl_pid=1352, nl_groups=00000000}, [12]) = 0
[pid  1352] 08:28:47.887369 sendto(7, [{nlmsg_len=20, nlmsg_type=0x16 /* NLMSG_??? */, nlmsg_flags=NLM_F_REQUEST|0x300, nlmsg_seq=1640334527, nlmsg_pid=0}, "\x00\x00\x00\x00"], 20, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 20

fd5 seems to be the normal system_bus_socket:

[pid  1352] 08:28:22.652961 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 5
[pid  1352] 08:28:22.653159 getsockopt(5, SOL_SOCKET, SO_RCVBUF, [180224], [4]) = 0
[pid  1352] 08:28:22.653371 setsockopt(5, SOL_SOCKET, SO_RCVBUF, [8388608], 4) = 0
[pid  1352] 08:28:22.653557 getsockopt(5, SOL_SOCKET, SO_RCVBUF, [360448], [4]) = 0
[pid  1352] 08:28:22.653752 setsockopt(5, SOL_SOCKET, SO_RCVBUFFORCE, [8388608], 4) = 0
[pid  1352] 08:28:22.653935 getsockopt(5, SOL_SOCKET, SO_SNDBUF, [180224], [4]) = 0
[pid  1352] 08:28:22.654132 setsockopt(5, SOL_SOCKET, SO_SNDBUF, [8388608], 4) = 0
[pid  1352] 08:28:22.654316 getsockopt(5, SOL_SOCKET, SO_SNDBUF, [360448], [4]) = 0
[pid  1352] 08:28:22.654510 setsockopt(5, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = 0
[pid  1352] 08:28:22.654695 connect(5, {sa_family=AF_UNIX, sun_path="/run/dbus/system_bus_socket"}, 30) = 0
[pid  1352] 08:28:22.654930 getsockopt(5, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
[pid  1352] 08:28:22.655141 getsockopt(5, SOL_SOCKET, SO_PEERSEC, 0x1a3e3c0, [64]) = -1 ENOPROTOOPT (Protocol not available)
[pid  1352] 08:28:22.655346 getsockopt(5, SOL_SOCKET, SO_PEERGROUPS, 0x1a37588, [256 => 0]) = 0
[pid  1352] 08:28:22.655555 fstat64(5, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
[pid  1352] 08:28:22.655749 getsockopt(5, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
[pid  1352] 08:28:22.655946 getsockname(5, {sa_family=AF_UNIX}, [128 => 2]) = 0
[pid  1352] 08:28:22.656143 sendmsg(5, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\0AUTH EXTERNAL\r\nDATA\r\n", iov_len=22}, {iov_base="NEGOTIATE_UNIX_FD\r\n", iov_len=19}, {iov_base="BEGIN\r\n", iov_len=7}], msg_iovlen=3, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 48

[Zarkoob]

As per another log issue similar to this: [pambase] support systemd-homed

For distro arch with Pacman I've found the easiest solution is perhaps to use NoExtract

Place this in /etc/pacman.conf
NoExtract = usr/lib/security/pam_systemd_home.so

Not sure other systemd distros how you'd block that file.