systemd 229 / dbus 1.10.6-1ubuntu3.5 (16.04) and systemd 237 / dbus 1.12.2-1ubuntu1.1 (18.04) error with "Failed to get properties: Access denied" when ran as non-root user

[Zahid Bukhari]

I've seen this bug reported but almost always it is when being ran as root. This however is only an issue when ran as a non-root user.

The root user is fine. I've come across this several times and although it's not a major issue, the only solution I've found is to reboot the system.

I see this when running strace, tracing the network.

We recently installed docker-ce and updated our version of salt from 2016.8.3 using python 2 to 2019.2.4 using python 3.

### 16.04 - systemd 229 on d1lmonitoringdev1 ###

## non-root user ##

$ strace -f -s 16384 -e trace=network systemctl status ntp
socket(PF_LOCAL, 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) = -1 EPERM (Operation not permitted)
setsockopt(3, SOL_SOCKET, SO_RCVBUF, [8388608], 4) = 0
getsockopt(3, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0
setsockopt(3, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = -1 EPERM (Operation not permitted)
setsockopt(3, SOL_SOCKET, SO_SNDBUF, [8388608], 4) = 0
connect(3, {sa_family=AF_LOCAL, sun_path="/var/run/dbus/system_bus_socket"}, 33) = 0
getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
getsockopt(3, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
getsockname(3, {sa_family=AF_LOCAL, NULL}, [2]) = 0
sendmsg(3, {msg_name(0)=NULL, msg_iov(3)=[{"\0AUTH EXTERNAL ", 15}, {"3130313631", 10}, {"\r\nNEGOTIATE_UNIX_FD\r\nBEGIN\r\n", 28}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 53
recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"REJECTED EXTERNAL DBUS_COOKIE_SHA1 ANONYMOUS\r\nERROR \"Need to authenticate first\"\r\n", 256}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 82
strace: Process 29413 attached
[pid 29413] --- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=29412, si_uid=10161} ---
Failed to get properties: Access denied
[pid 29413] +++ exited with 0 +++
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=29413, si_uid=10161, si_status=0, si_utime=0, si_stime=0} ---
+++ exited with 1 +++

## root user ##

# Truncated because as root it works.
$ sudo strace -f -s 16384 -e trace=network systemctl status ntp
[sudo] password for zbukhari:
socket(PF_LOCAL, 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_LOCAL, sun_path="/run/systemd/private"}, 22) = 0
getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
getsockopt(3, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0
getsockname(3, {sa_family=AF_LOCAL, NULL}, [2]) = 0
sendmsg(3, {msg_name(0)=NULL, msg_iov(3)=[{"\0AUTH EXTERNAL ", 15}, {"30", 2}, {"\r\nNEGOTIATE_UNIX_FD\r\nBEGIN\r\n", 28}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 45
getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"OK 3139491ef18e4f4c84fae863d4dd042f\r\nAGREE_UNIX_FD\r\n", 256}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 52
sendmsg(3, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\4\1\5\0\0\0\1\0\0\0\237\0\0\0\1\1o\0,\0\0\0/org/freedesktop/systemd1/unit/ntp_2eservice\0\0\0\0\3\1s\0\6\0\0\
0GetAll\0\0\2\1s\0\37\0\0\0org.freedesktop.DBus.Properties\0\6\1s\0\30\0\0\0org.freedesktop.systemd1\0\0\0\0\0\0\0\0\10\1g\0\1s\0\0", 176}, {"\0\0\0\0\0", 5}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 181
recvmsg(3, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\35 \0\0\1\0\0\0\23\0\0\0\5\1u\0\1\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24

### 18.04 - systemd 237 on d1lzbbyodev1 ###

## non-root user ##
$ strace -f -s 16384 -e trace=%network systemctl status ntp
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) = -1 EPERM (Operation not permitted)
setsockopt(3, SOL_SOCKET, SO_RCVBUF, [8388608], 4) = 0
getsockopt(3, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0
setsockopt(3, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = -1 EPERM (Operation not permitted)
setsockopt(3, SOL_SOCKET, SO_SNDBUF, [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, 0x56338b39b450, [64]) = -1 ENOPROTOOPT (Protocol not available)
getsockopt(3, SOL_SOCKET, SO_PEERGROUPS, "", [256->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 ", iov_len=15}, {iov_base="3130313631", iov_len=10}, {iov_base="\r\nNEGOTIATE_UNIX_FD\r\nBEGIN\r\n", iov_len=28}], msg_iovlen=3, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 53
strace: Process 22703 attached
[pid 22702] recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="REJECTED EXTERNAL\r\nERROR \"Need to authenticate first\"\r\n", iov_len=256}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 55
[pid 22703] --- SIGCONT {si_signo=SIGCONT, si_code=SI_USER, si_pid=22702, si_uid=10161} ---
Failed to get properties: Access denied
[pid 22703] +++ exited with 0 +++
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=22703, si_uid=10161, si_status=0, si_utime=0, si_stime=0} ---
+++ exited with 1 +++

## root user ##

# truncated because as root it works.
$ sudo strace -f -s 16384 -e trace=%network systemctl status ntp
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/systemd/private"}, 22) = 0
getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
getsockopt(3, SOL_SOCKET, SO_PEERSEC, 0x557f1d186450, [64]) = -1 ENOPROTOOPT (Protocol not available)
getsockopt(3, SOL_SOCKET, SO_PEERGROUPS, "", [256->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 ", iov_len=15}, {iov_base="30", iov_len=2}, {iov_base="\r\nNEGOTIATE_UNIX_FD\r\nBEGIN\r\n", iov_len=28}], msg_iovlen=3, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 45
getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=0, gid=0}, [12]) = 0
strace: Process 22999 attached
[pid 22998] recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="OK fd99f58716884af9a7c053f7d08a1db0\r\nAGREE_UNIX_FD\r\n", iov_len=256}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 52
[pid 22998] sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\4\1\5\0\0\0\1\0\0\0\237\0\0\0\1\1o\0,\0\0\0/org/freedesktop/systemd1/unit/ntp_2eservice\0\0\0\0\3\1s\0\6\0\0\0GetAll\0\0\2\1s\0\37\0\0\0org.freedesktop.DBus.Properties\0\6\1s\0\30\0\0\0org.freedesktop.systemd1\0\0\0\0\0\0\0\0\10\1g\0\1s\0\0", iov_len=176}, {iov_base="\0\0\0\0\0", iov_len=5}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 181
[pid 22998] recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1Q(\0\0\1\0\0\0;\0\0\0\5\1u\0\1\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24

[Zahid Bukhari (cimmerian)]

I tried to use "kill -TERM 1" but that didn't work. Along with daemon-reload and daemon-reexec, that still hasn't worked. A key difference here compared to other similar complaints is that this is with non-root users, as the root user it's fine. As such it's not critical, however as there are some services / units that can be used by users, it may be an issue for others as sometimes a reboot can't be done.

[Dan Streetman (ddstreet)]

systemd isn't your problem, dbus is rejecting the connection.

[Zahid Bukhari (cimmerian)]

I know that, strace shows it, but as we do use LDAP and so far all other software works fine and realizes that we are logged in, systemd goes to dbus and determines we aren't authenticated.

Most of these would result in system calls ... actually before I type too much, can this be moved to "dbus" then? I can move it if possible, I just wanted to get a conversation going and felt that since systemd, dbus, etc are under freedesktop it may be related and I don't directly use dbus, but I do use systemd :-)

Thanks!

[Zahid Bukhari (cimmerian)]

This is related with systemd and dbus. Possibly nsswitch, ldap and nscd.

However dbus sees the user as not being authenticated. As such, I'm switching this over to dbus.

We see this issue every now and then depending on what we install so I feel there's a race condition taking place which affects the order. I'll put more details below, hopefully we can at least advise others on this particular scenario if it's not a bug, however as systemd has before, after methods, perhaps we can refine the unit files?

[Zahid Bukhari (cimmerian)]

We have ldap.conf set to mode 440 as there is a sensitive password used in our config to bind to LDAP. This works for everything else that needs it even at the user level via normal system calls.

However from what I can tell, dbus seems to need to be able to read the file from an strace my co-workers ran. In all my tests I didn't see it go to strace, and this was prior to specifying the network, however in their test run, they say an access denied for /etc/ldap.conf.

Just now I ran a test where I chmod'd it to be 444, and then ran systemctl as a normal user, it worked.

My co-workers ran an strace against the dbus process and saw it was trying to read /etc/ldap.conf. I'm not sure why it would need that versus just using syscalls.

Anyway, it worked. So then I changed it back, changed into a different user, it still worked. Then I tried to invalidate nscd cache, it still worked.

So I feel depending on what starts and or restarts where, it's a draw as to whether or not it'll work.

I'm checking to see if dbus caches LDAP creds but also going to try and separate ldap.conf creds to another file.

Thank you!

[Zahid Bukhari (cimmerian)]

In my testing, using rootbinddn and separating LDAP info and LDAP creds to separate files with ldap.conf as 444 and ldap.secret as 400 didn't work for dbus.

I did change the group to messagebus and that worked.

[Ryan Phelps (ryancerium)]

Here's an annotated strace output of the dbus process when it fails. In another terminal, I ran 'systemctl status ntp' which triggers the dbus query. As Zahid mentioned above, this is with the permissions on /etc/ldap.conf set to 440, so the dbus-daemon user doesn't have permissions to read it. But why does dbus-daemon _want_ to read it? It's also checking /etc/passwd before this.

rphelps@d1lmdbsvrstg2:~$ sudo strace -p 942 -s 256
strace: Process 942 attached
epoll_wait(4, [{EPOLLIN, {u32=3, u64=386346997063352323}}], 64, -1) = 1

# Accept the incoming dbus call from systemctl
accept4(3, {sa_family=AF_LOCAL, NULL}, [2], SOCK_CLOEXEC) = 18

# Set it to a non-blocking socket, add it to the epoll() list, and call epoll() again
fcntl(18, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(18, F_SETFL, O_RDWR|O_NONBLOCK) = 0
getsockname(18, {sa_family=AF_LOCAL, sun_path="/var/run/dbus/system_bus_socket"}, [34]) = 0
epoll_ctl(4, EPOLL_CTL_ADD, 18, {EPOLLET, {u32=18, u64=386346997063352338}}) = 0
epoll_ctl(4, EPOLL_CTL_MOD, 18, {EPOLLIN, {u32=18, u64=14407806993769168914}}) = 0
epoll_wait(4, [{EPOLLIN, {u32=18, u64=14407806993769168914}}], 64, 29999) = 1

# Read a message from systemctl
recvmsg(18, {msg_name(0)=NULL, msg_iov(1)=[{"\0", 1}], msg_controllen=0, msg_flags=0}, 0) = 1

# Get the pid, uid, and gid of the systemctl process, rphelps in this case
getsockopt(18, SOL_SOCKET, SO_PEERCRED, {pid=17258, uid=10247, gid=10004}, [12]) = 0

# Try and fail to get the peer socket security state, but that might be SELinux only?
getsockopt(18, SOL_SOCKET, SO_PEERSEC, 0x559bc7f68180, 0x7ffc93c3a2bc) = -1 ENOPROTOOPT (Protocol not available)

# Read the auth request from systemctl
read(18, "AUTH EXTERNAL 3130323437\r\nNEGOTIATE_UNIX_FD\r\nBEGIN\r\n", 2048) = 52

# Check the /etc/passwd for something
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 19
lseek(19, 0, SEEK_CUR) = 0
fstat(19, {st_mode=S_IFREG|0644, st_size=2014, ...}) = 0
mmap(NULL, 2014, PROT_READ, MAP_SHARED, 19, 0) = 0x7f5305a0d000
lseek(19, 2014, SEEK_SET) = 2014
fstat(19, {st_mode=S_IFREG|0644, st_size=2014, ...}) = 0
munmap(0x7f5305a0d000, 2014) = 0
close(19) = 0

# No idea
rt_sigaction(SIGPIPE, {SIG_IGN, [], SA_RESTORER, 0x7f530490a390}, {SIG_IGN, [], SA_RESTORER, 0x7f530490a390}, 8) = 0

# No idea why they're doing this; maybe to see if the caller is the same process?
geteuid() = 107

# Try, and fail, to open /etc/ldap.conf
open("/etc/ldap.conf", O_RDONLY) = -1 EACCES (Permission denied)
rt_sigaction(SIGPIPE, {SIG_IGN, [], SA_RESTORER, 0x7f530490a390}, NULL, 8) = 0

# Do another epoll() round
epoll_ctl(4, EPOLL_CTL_MOD, 18, {EPOLLET, {u32=18, u64=4294967314}}) = 0
epoll_ctl(4, EPOLL_CTL_MOD, 18, {EPOLLOUT, {u32=18, u64=4294967314}}) = 0
epoll_wait(4, [{EPOLLOUT, {u32=18, u64=4294967314}}], 64, 29995) = 1

# Send the rejection message to systemctl
sendto(18, "REJECTED EXTERNAL DBUS_COOKIE_SHA1 ANONYMOUS\r\nERROR \"Need to authenticate first\"\r\n", 82, MSG_NOSIGNAL, NULL, 0) = 82

# Remove the connection to systemctl from the epoll() list, and close the socket
epoll_ctl(4, EPO...