Re: systemd's connections to /run/systemd/private ?

[Brian Reichert <reichert@xxxxxxxxxxx>]

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.

- I didn't say anything about lines between those that I cited, as
  I could not ascertain relevance.

- And I completely missed the case of the accept4() calls returning
  the value of 19, among other cases where '19' shows up as a value.

A regex-based search is certainly inconclusive, but now I'm using this:

  egrep -e '[^0-9:]19(\)|\}|\]|,)?' /home/systemd.strace.trimmed | less

The rhythm now seems to be more like this:

  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
  ...

Mind you, I see a _lot_ more close() calls than accepts():

  localhost:~ # egrep -e '[^0-9:]19(\)|\}|\]|,)?' /home/systemd.strace.trimmed > /home/systemd.strace.trimmed.19
  localhost:~ # grep accept4\( /home/systemd.strace.trimmed.19 | cut -d' ' -f 2- | sort -u
  accept4(13, 0, NULL, SOCK_CLOEXEC|SOCK_NONBLOCK) = 19
  localhost:~ # grep accept4\( /home/systemd.strace.trimmed.19 | cut -d' ' -f 2- | wc -l
  55
  localhost:~ # grep close\( /home/systemd.strace.trimmed.19 | cut -d' ' -f 2- | sort -u
  close(19)                      = 0
  localhost:~ # grep close\( /home/systemd.strace.trimmed.19 | cut -d' ' -f 2- | wc -l
  1051

I'm not asserting the frequencies are indicative of anything wrong;
I'm just more used to a 1:1 correlation.

And, again, the age of the file in /proc/1/fd/19 never seems to
change:

  localhost:~ # ls -ld --full-time /proc/1/fd/19
  lrwx------ 1 root root 64 2019-07-30 15:45:25.531468318 -0400 /proc/1/fd/19
  -> socket:[27085]
  localhost:~ # date
  Wed Jul 31 11:31:37 EDT 2019

That may be a red herring. I have been assuming that if an FD was
closed, then reopened/recreated by a process, that file would have
a new age.





> 
> 
> _______________________________________________
> systemd-devel mailing list
> systemd-devel@xxxxxxxxxxxxxxxxxxxxx
> https://lists.freedesktop.org/mailman/listinfo/systemd-devel

-- 
Brian Reichert				<reichert@xxxxxxxxxxx>
BSD admin/developer at large	
_______________________________________________
systemd-devel mailing list
systemd-devel@xxxxxxxxxxxxxxxxxxxxx
https://lists.freedesktop.org/mailman/listinfo/systemd-devel