[systemd-devel] systemd's connections to /run/systemd/private ?

[Zbigniew Jędrzejewski-Szmek]

On Wed, Jul 31, 2019 at 11:37:31AM -0400, Brian Reichert wrote:
> On Wed, Jul 31, 2019 at 12:36:41AM +0300, Uoti Urpala wrote:
> > On Tue, 2019-07-30 at 14:56 -0400, Brian Reichert wrote:
> > > I see, between 13:49:30 and 13:50:01, I see 25 'successful' calls
> > > for close(), e.g.:
> > > 
> > > 	13:50:01 close(19)                      = 0
> > > 
> > > Followed by getsockopt(), and a received message on the supposedly-closed
> > > file descriptor:
> > > 
> > >   13:50:01 getsockopt(19, SOL_SOCKET, SO_PEERCRED, {pid=3323, uid=0, gid=0}, [12]) = 0
> > 
> > Are you sure it's the same file descriptor? You don't explicitly say
> > anything about there not being any relevant lines between those. Does
> > systemd really just call getsockopt() on fd 19 after closing it, with
> > nothing to trigger that? Obvious candidates to check in the strace
> > would be an accept call returning a new fd 19, or epoll indicating
> > activity on the fd (though I'd expect systemd to remove the fd from the
> > epoll set after closing it).
> 
> My analysis is naive.
> 
> There was an earlier suggestion to use strace, limiting it to a
> limited number of system calls.
> 
> I then used a simple RE to look for the string '(19', to see calls where
> '19' was used as an initial argument to system calls.  That's way too
> simplistic.
> 
> To address some of your questions/points.
> 
> - No, I don't know if it's the same file descriptor.  I could not
>   start strace early enough to catch the creation of several dozen
>   file descriptors.

This shouldn't really matter. We care about descriptors which are
created while the process is running, so it is not a problem if we
"miss" some that are created early.

>   13:50:01 accept4(13, 0, NULL, SOCK_CLOEXEC|SOCK_NONBLOCK) = 19
>   13:50:01 getsockopt(19, SOL_SOCKET, SO_PEERCRED, {pid=3323, uid=0, gid=0}, [12]) = 0
>   13:50:01 getsockopt(19, SOL_SOCKET, SO_RCVBUF, [4194304], [4]) = 0
>   13:50:01 getsockopt(19, SOL_SOCKET, SO_SNDBUF, [262144], [4]) = 0
>   13:50:01 getsockopt(19, SOL_SOCKET, SO_PEERCRED, {pid=3323, uid=0, gid=0}, [12]) = 0
>   13:50:01 getsockopt(19, SOL_SOCKET, SO_ACCEPTCONN, [0], [4]) = 0 13:50:01 getsockname(19, {sa_family=AF_LOCAL, sun_path="/run/systemd/private"}, [23]) = 0 13:50:01 recvmsg(19, {msg_name(0)=NULL, msg_iov(1)=[{"\0AUTH EXTERNAL 30\r\nNEGOTIATE_UNIX_FD\r\nBEGIN\r\n", 256}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 45
>   13:50:01 sendmsg(19, {msg_name(0)=NULL, msg_iov(3)=[{"OK 9fcf621ece0a4fe897586e28058cd2fb\r\nAGREE_UNIX_FD\r\n", 52}, {NULL, 0}, {NULL, 0}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 52 13:50:01 sendmsg(19, {msg_name(0)=NULL, msg_iov(2)=[{"l\4\1\1P\0\0\0\1\0\0\0p\0\0\0\1\1o\0\31\0\0\0/org/freedesktop/systemd1\0\0\0\0\0\0\0\2\1s\0 \0\0\0org.freedesktop.systemd1.Manager\0\0\0\0\0\0\0\0\3\1s\0\7\0\0\0UnitNew\0\10\1g\0\2so\0", 128}, {"\20\0\0\0session-11.scope\0\0\0\0003\0\0\0/org/freedesktop/systemd1/unit/session_2d11_2escope\0", 80}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = -1 EPIPE (Broken pipe)
>   13:50:01 close(19)                      = 0
>   13:50:01 close(19)                      = 0
>   13:50:01 close(19)                      = 0
>   13:50:01 close(19)                      = 0
>   13:50:01 close(19)                      = 0
>   13:50:01 close(19)                      = 0
>   13:50:01 close(19)                      = 0

The kernel will use the lower-numbered available fd, so there's lot of
"reuse" of the same numbers happening. This strace means that between
each of those close()s here, some other function call returned fd 19.
Until we know what those calls are, we cannot say why fd19 remains
open. (In fact, the only thing we can say for sure, is that the
accept4() call shown above is not relevant.)

Zbyszek