containers / containers/toolbox

delays caused by dbus in 0.0.99

Open
#671 5 comments 0 reactions 0 assignees View on GitHub
1. Bug 1. Regression 2. Container Realm 7. Need Information
Dominant language
Go
Stars
3.5k
Forks
262
Avg merge
3d 1h
Merged PRs (30d)
1

Description

**Describe the bug**
After updating my Fedora 33 to toolbox 0.0.99, I notice long start time (several seconds) of some applications, namely `mc`.
When running with `strace -T -o out.log mc`, I can see
```
socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, 0) = 3 <0.000024>
getsockopt(3, SOL_SOCKET, SO_RCVBUF, [212992], [4]) = 0 <0.000007>
setsockopt(3, SOL_SOCKET, SO_RCVBUF, [8388608], 4) = 0 <0.000007>
getsockopt(3, SOL_SOCKET, SO_RCVBUF, [425984], [4]) = 0 <0.000005>
setsockopt(3, SOL_SOCKET, SO_RCVBUFFORCE, [8388608], 4) = -1 EPERM (Operation not permitted) <0.000005>
getsockopt(3, SOL_SOCKET, SO_SNDBUF, [212992], [4]) = 0 <0.000005>
setsockopt(3, SOL_SOCKET, SO_SNDBUF, [8388608], 4) = 0 <0.000005>
getsockopt(3, SOL_SOCKET, SO_SNDBUF, [425984], [4]) = 0 <0.000005>
setsockopt(3, SOL_SOCKET, SO_SNDBUFFORCE, [8388608], 4) = -1 EPERM (Operation not permitted) <0.000005>
connect(3, {sa_family=AF_UNIX, sun_path="/run/dbus/system_bus_socket"}, 30) = 0 <0.000018>
getsockopt(3, SOL_SOCKET, SO_PEERCRED, {pid=1, uid=65534, gid=65534}, [12]) = 0 <0.000006>
getsockopt(3, SOL_SOCKET, SO_PEERSEC, "system_u:system_r:system_dbusd_t"..., [64->36]) = 0 <0.000008>
getsockopt(3, SOL_SOCKET, SO_PEERGROUPS, 0x55958ed0de20, [256->0]) = 0 <0.000005>
fstat(3, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0 <0.000005>
getsockopt(3, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0 <0.000005>
getsockname(3, {sa_family=AF_UNIX}, [128->2]) = 0 <0.000006>
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 <0.000012>
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="DATA\r\nOK 62499daace1df01c0c0432b"..., iov_len=256}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 58 <0.000010>
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 <0.000009>
recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=24, tv_nsec=999951000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=24, tv_nsec=999950159}) <0.000006>
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\2\1\1\v\0\0\0\377\377\377\377?\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_CMSG_CLOEXEC) = 24 <0.000006>
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0"..., iov_len=67}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 67 <0.000012>
sendmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\1\2\1 \0\0\0\2\0\0\0\242\0\0\0\1\1o\0\31\0\0\0/org/fre"..., iov_len=184}, {iov_base="\0\0\0\0\7\0\0\0TOOLBOX\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", iov_len=32}], msg_iovlen=2, msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 216 <0.000011>
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\4\1\1\v\0\0\0\377\377\377\377\217\0\0\0\7\1s\0\24\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24 <0.000006>
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="org.freedesktop.DBus\0\0\0\0\6\1s\0\6\0\0\0"..., iov_len=147}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 147 <0.000007>
recvmsg(3, {msg_namelen=0}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = -1 EAGAIN (Resource temporarily unavailable) <0.000005>
ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=119, tv_nsec=999933000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=119, tv_nsec=1179715}) <0.998779>
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="l\3\1\1;\0\0\0\314\t\0\0^\0\0\0\5\1u\0\2\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 24 <0.000014>
recvmsg(3, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\6\1s\0\6\0\0\0:1.783\0\0\4\1s\0&\0\0\0org.free"..., iov_len=147}], msg_iovlen=1, msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_CMSG_CLOEXEC) = 147 <0.000026>
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000011>
close(3) = 0 <0.000012>
```
repeated several times.

Notice almost one second delay caused by
`ppoll([{fd=3, events=POLLIN}], 1, {tv_sec=119, tv_nsec=999933000}, NULL, 8) = 1 ([{fd=3, revents=POLLIN}], left {tv_sec=119, tv_nsec=1179715}) <0.998779>`

**Steps how to reproduce the behaviour**
1. Run `mc` in up-to-date Fedora 33 toolbox running on up-to-date Fedora 33
2. Notice the delay

**Expected behaviour**
No delay when starting applications.

**Output of `toolbox --version` (v0.0.90+)**
`toolbox version 0.0.99`

**Toolbox package info (`rpm -q toolbox`)**
`toolbox-0.0.99-1.fc33.x86_64`

**Output of `podman version`**
```
Version: 2.2.1
API Version: 2.1.0
Go Version: go1.15.5
Built: Tue Dec 8 15:37:50 2020
OS/Arch: linux/amd64
```

**Podman package info (`rpm -q podman`)**
`podman-2.2.1-1.fc33.x86_64`

**Info about your OS**
Fedora Workstation 33

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.