2

Using Oracle Linux 8.6 we're having an issue with timedatectl but only when it's run by systemd(239-58.0.1.el8_6.3) during ExecStartPre in a .service definition file and SELinux is set to Enforcing.

Important!: The command timedatectl show works when run:

  • By the user in the shell
  • If we run it within a script under ExecStart instead of ExecStartPre
  • If we run it directly in the ExecStartPre line as ExecStartPre=timedatectl show

MinimalRepro:

/test.sh:

#!/usr/bin/bash timedatectl show

/usr/lib/systemd/system/test.service

[Unit] Description=Test Service [Service] Type=simple TimeoutStopSec=60s #This is necessary as this is a timeout issue SyslogIdentifier=test ExecStartPre=+/usr/bin/bash /test.sh ExecStart=echo "Done!"

With these files in place, run the command systemctl start test

Result:

The service fails to start. Journalctl shows "Failed to parse bus message: Connection timed out"

strace logs:

We managed to gather strace output during the failure. The relevant part (after dependency loads):

access("/etc/selinux/config", F_OK) = 0 openat(AT_FDCWD, "/proc/sys/crypto/fips_enabled", O_RDONLY) = 3 read(3, "0\n", 2) = 2 close(3) = 0 access("/etc/system-fips", F_OK) = -1 ENOENT (No such file or directory) access("/etc/system-fips", F_OK) = -1 ENOENT (No such file or directory) access("/etc/gcrypt/fips_enabled", F_OK) = -1 ENOENT (No such file or directory) openat(AT_FDCWD, "/proc/sys/crypto/fips_enabled", O_RDONLY) = 3 fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 read(3, "0\n", 1024) = 2 close(3) = 0 prctl(PR_CAPBSET_READ, CAP_MAC_OVERRIDE) = 1 prctl(PR_CAPBSET_READ, 0x30 /* CAP_??? */) = -1 EINVAL (Invalid argument) prctl(PR_CAPBSET_READ, CAP_CHECKPOINT_RESTORE) = -1 EINVAL (Invalid argument) prctl(PR_CAPBSET_READ, CAP_BLOCK_SUSPEND) = 1 prctl(PR_CAPBSET_READ, CAP_PERFMON) = -1 EINVAL (Invalid argument) prctl(PR_CAPBSET_READ, CAP_AUDIT_READ) = 1 openat(AT_FDCWD, "/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=217800224, ...}) = 0 mmap(NULL, 217800224, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f3238c29000 close(3) = 0 openat(AT_FDCWD, "/proc/self/stat", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 read(3, "14656 (timedatectl) R 14653 1463"..., 1024) = 313 close(3) = 0 access("/proc/vz", F_OK) = -1 ENOENT (No such file or directory) getpid() = 14656 openat(AT_FDCWD, "/run/systemd/container", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory) openat(AT_FDCWD, "/proc/1/environ", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0400, st_size=0, ...}) = 0 read(3, "HOME=/\0TERM=linux\0BOOT_IMAGE=(hd"..., 1024) = 99 read(3, "", 1024) = 0 close(3) = 0 openat(AT_FDCWD, "/proc/1/sched", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 read(3, "systemd (1, #threads: 1)\n-------"..., 1024) = 1024 close(3) = 0 openat(AT_FDCWD, "/proc/cmdline", O_RDONLY|O_CLOEXEC) = 3 fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0 read(3, "BOOT_IMAGE=(hd0,msdos1)/vmlinuz-"..., 1024) = 183 close(3) = 0 openat(AT_FDCWD, "/", O_RDONLY|O_NOCTTY|O_CLOEXEC|O_PATH) = 3 fstatfs(3, {f_type=XFS_SB_MAGIC, f_bsize=4096, f_blocks=18341120, f_bfree=16244361, f_bavail=16244361, f_files=36700160, f_ffree=36548894, f_fsid={val=[0xfc00, 0]}, f_namelen=255, f_frsize=4096, f_flags=ST_VALID|ST_RELATIME}) = 0 close(3) = 0 access("/etc/initrd-release", F_OK) = -1 ENOENT (No such file or directory) newfstatat(AT_FDCWD, "/run/systemd/system/", {st_mode=S_IFDIR|0755, st_size=40, ...}, AT_SYMLINK_NOFOLLOW) = 0 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3 getsockopt(3, SOL_SOCKET, SO_RCVBUF, [212992], [4]) = 0 setsockopt(3, SOL_SOCKET, SO_RCVBUFFORCE, [8388608], 4) = 0 getsockopt(3, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0 setsockopt(3, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = 0 connect(3, {sa_family=AF_UNIX, sun_path="/run/dbus/system_bus_socket"}, 29) = 0 getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0 getsockopt(3, SOL_SOCKET, SO_PEERSEC, "system_u:system_r:system_dbusd_t"..., [64 => 36]) = 0 getsockopt(3, SOL_SOCKET, SO_PEERGROUPS, 0x55ed61e47c60, [256 => 0]) = 0 fstat(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 getsockopt(3, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0 getsockname(3, {sa_family=AF_UNIX}, [128 => 2]) = 0 sendmsg(3, {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 gettid() = 14656 getrandom("\x26\x61\x8e\x0f\x4d\x7f\x4e\x6f\x8f\x4f\xfa\x3e\x40\xa5\xe0\x25", 16, GRND_NONBLOCK) = 16 gettid() = 14656 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="DATA\r\nOK a4090baa394dcf0c365870c"..., iov_len=256}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 58 sendmsg(3, {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 recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999768000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=24, tv_nsec=999316712}) recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\f\0\0\0\1\0\0\0=\0\0\0\6\1s\0\7\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base=":1.4092\0\5\1u\0\1\0\0\0\10\1g\0\1s\0\0\7\1s\0\24\0\0\0"..., iov_len=68}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 68 sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\0\1\5\0\0\0\2\0\0\0\217\0\0\0\1\1o\0\32\0\0\0/org/fre"..., iov_len=160}, {iov_base="\0\0\0\0\0", iov_len=5}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 165 recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\4\1\1\f\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 recvmsg(3, {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=148}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 148 recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999676000}, NULL, 8) = 0 (Timeout) openat(AT_FDCWD, "/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 4 fstat(4, {st_mode=S_IFREG|0644, st_size=2997, ...}) = 0 read(4, "# Locale name alias data base.\n#"..., 4096) = 2997 read(4, "", 4096) = 0 close(4) = 0 openat(AT_FDCWD, "/usr/share/locale/en_US.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) openat(AT_FDCWD, "/usr/share/locale/en_US.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) openat(AT_FDCWD, "/usr/share/locale/en_US/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) openat(AT_FDCWD, "/usr/share/locale/en.UTF-8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) openat(AT_FDCWD, "/usr/share/locale/en.utf8/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) openat(AT_FDCWD, "/usr/share/locale/en/LC_MESSAGES/libc.mo", O_RDONLY) = -1 ENOENT (No such file or directory) writev(2, [{iov_base="Failed to parse bus message: Con"..., iov_len=49}, {iov_base="\n", iov_len=1}], 2) = 50 close(3) = 0 exit_group(1) = ? +++ exited with 1 +++

Log findings:

From the logs it seems clear to me that timedatectl did successfully reach out for information from the servers by the presence of the recvmsg commands throughout. However, the ppol on the socket with fd 3, doesn't appear to be closing correctly. Running strace with timestamps shows that ppol is the only command that is taking a significant amount of time and the recvmsg commands are done long before the timeout occurs.

Audit.log:

I found the following in the audit logs that coincide with the failures:

type=USER_ACCT msg=audit(1660774510.696:6426767): pid=1298671 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:initrc_t:s0 msg='op=PAM:accounting grantors=pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset" type=USER_CMD msg=audit(1660774510.697:6426768): pid=1298671 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:initrc_t:s0 msg='cwd="/" cmd=74696D656461746563746C2073686F77 exe="/usr/bin/sudo" terminal=? res=success'UID="root" AUID="unset" type=CRED_REFR msg=audit(1660774510.697:6426769): pid=1298671 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:initrc_t:s0 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset" type=USER_START msg=audit(1660774510.706:6426770): pid=1298671 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:initrc_t:s0 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset" type=SERVICE_START msg=audit(1660774510.780:6426771): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-timedated comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset" type=USER_AVC msg=audit(1660774510.783:6426772): pid=966 uid=81 auid=4294967295 ses=4294967295 subj=system_u:system_r:system_dbusd_t:s0-s0:c0.c1023 msg='avc: denied { send_msg } for msgtype=method_return dest=:1.3078967 spid=1298674 tpid=1298673 scontext=system_u:system_r:systemd_timedated_t:s0 tcontext=system_u:system_r:initrc_t:s0 tclass=dbus permissive=0 exe="/usr/bin/dbus-daemon" sauid=81 hostname=? addr=? terminal=?'UID="dbus" AUID="unset" SAUID="dbus"

Variations:

The following changes had no effect (error continued)

  • Added a user/group definition to the test file and ran the ExecStartPre command as the user and as root
  • Ran the script using /usr/bin/sh
  • Ran the script using /usr/bin/zsh
  • Ran the timedatectl show command under sudo

Questions:

  • What could potentially cause ppol to hang like this?
  • How could we determine what it's actually waiting for when it seems the recvmsg commands have returned everything expected of them?
  • Is there anything else we can do to SELinux to fix this besides setting it to Permissive?
Improve this question

1 Answer 1

Reset to default
1

I found the answer to my own question shortly after asking it (Though, I would still love to know why this occurs with ExecStartPre but not ExecStart, if anyone can clue me in on that).

The problem is that, by default, SELinux is blocking initrc_t:dbus send_msg. The easiest way to bypass this is setting SELinux to permissive, but that's obviously far from ideal. Instead, we need to create a policy with the following steps.

  1. Install policycoreutils-devel with: dnf install -y policycoreutils-devel
  2. After finding the audit msg number in the audit.log file (see audit.log snippet in question "1660774510"), feed the appropriate lines into the audit2allow utility to generate a policy file: cat /var/log/audit/audit.log | grep 1660774510 | audit2allow -M newPolicy
  3. Use semodule to apply the new policy: semodule -i newPolicy.pp
Note:

To incentivize other, possibly more detailed answers (hopefully explaining the ExecStartPre versus ExecStart thing), I'll hold off on accepting my own answer for now and will accept the best after some time has passed.

Improve this answer

You must log in to answer this question.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.