Uploaded image for project: 'RHEL'
  1. RHEL
  2. RHEL-138414

systemd complains with "Can't open PID file /run/restorecond.pid (yet?) after start: Operation not permitted", which is a confusing message

Linking RHIVOS CVEs to...Migration: Automation ...SWIFT: POC ConversionSync from "Extern...XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Undefined Undefined
    • rhel-9.8
    • rhel-9.7
    • systemd
    • None
    • None
    • Low
    • rhel-systemd
    • None
    • False
    • False
    • Hide

      None

      Show
      None
    • No
    • None
    • None
    • None
    • Unspecified Release Note Type - Unknown
    • Unspecified
    • Unspecified
    • Unspecified
    • None

      What were you trying to do that didn't work?

      Very often, when restorecond service start (service delivered by policycoreutils-restorecond package), the following message is seen:

      # systemctl status restorecond
      [...]
      Jan 05 14:20:29 vm-rhel9 systemd[1]: Starting Restorecon maintaining path file context...
      Jan 05 14:20:29 vm-rhel9 systemd[1]: restorecond.service: Can't open PID file /run/restorecond.pid (yet?) after start: Operation not permitted
      Jan 05 14:20:29 vm-rhel9 systemd[1]: Started Restorecon maintaining path file context.
      

      This message is confusing and also wrong: there is no EPERM here (as seen with stracing), because in fact /run/restorecond.pid doesn't exist yet, it should return ENOENT if any message is really needed here (I believe this message should just not show up at all).

      The root cause for seeing this is restorecond forked to become a daemon but didn't write its PID file yet.

      What is the impact of this issue to you?

      Annoyance

      Please provide the package NVR for which the bug is seen:

      systemd-252-55.el9_7.7

      How reproducible is this bug?

      Very often.
      Always with reproducer below.

      Steps to reproduce

      1. Stop restorecond service
        # systemctl stop restorecond
      2. Install/configure systemtap
        # yum -y install systemtap yum-utils
        # stap-prep
        # debuginfo-install policycoreutils-restorecond
        
      3. Execute systemtap script below to delay restorecond between its fork and PID file creation
        # stap -v -g -e 'probe process("/usr/sbin/restorecond").statement("*@restorecond.c:217") { mdelay(500); }'
      4. In another terminal start the service while stracing systemd
        # strace -ttTvyy -s 256 -o systemd.strace -p 1 &
        # systemctl start restorecond

      Expected results

      Service starts without printing "Can't open PID file ..." message.

      Actual results

      [...]
      1     14:20:29.618691 openat(80</run>, "restorecond.pid", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = -1 ENOENT (No such file or directory) <0.000006>
      1     14:20:29.618708 close(80</run>)   = 0 <0.000002>
      1     14:20:29.618723 gettid()          = 1 <0.000002>
      1     14:20:29.618735 sendmsg(24<UNIX:[16659->14312]>, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PRIORITY=6\nSYSLOG_FACILITY=3\nTID=1\nCODE_FILE=src/core/service.c\nCODE_LINE=992\nCODE_FUNC=service_load_pid_file\nUNIT=restorecond.service\nINVOCATION_ID=18e3ef03768f4b6eadb165cc3cf210d2\nSYSLOG_IDENTIFIER=systemd\n", iov_len=208}, {iov_base="MESSAGE=", iov_len=8}, {iov_base="restorecond.service: Can't open PID file /run/restorecond.pid (yet?) after start: Operation not permitted", iov_len=105}, {iov_base="\n", iov_len=1}], msg_iovlen=4, msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 322 <0.000010>
      

              fsumsalrh Frantisek Sumsal
              rhn-support-rmetrich Renaud Métrich
              systemd maint mailing list systemd maint mailing list
              Frantisek Sumsal Frantisek Sumsal
              Votes:
              0 Vote for this issue
              Watchers:
              10 Start watching this issue

                Created:
                Updated: