Bug#926896: sysvinit-utils: pidof is unreliable

[Martin von Wittich]

Am 20.10.19 um 20:59 schrieb Dmitry Bogatov:
> 
> That sounds explainable. pidof() scans /proc directory, and it takes some
> time for kernel to create entry there.

Hm, is there really a delay? I'm not very deep into kernel development, 
but as far as I understand /proc, it isn't populated by the kernel after 
a process has been created, but instead represents direct access to 
internal kernel data structures. So as far as I know, there shouldn't be 
any delay after a process has been created before it's accessible via 
/proc/<pid>.

Even if there were, that wouldn't explain how ps is able to see the 
process, while pidof is not. As far as I know, ps also gets this 
information from /proc.

To verify my assumptions, I've adapted my test script as follows:

#!/bin/bash

set -eu
systemctl restart apcupsd
START=$SECONDS

ps -f -C apcupsd
PID="$(ps -o pid -C apcupsd --noheaders)"
ls /proc/"$PID"

while true
do
   echo -n "pidof: "
   pidof -s apcupsd || echo
   echo -n "ls: "
   ls -d /proc/"$PID"
   [ $((SECONDS - START)) -ge 2 ] && break
   sleep 0.01
done
ps -f -C apcupsd


The output:

buster-server ~ # ./pidof.sh
UID        PID  PPID  C STIME TTY          TIME CMD
root     26476     1  0 14:16 ?        00:00:00 /sbin/apcupsd
attr       clear_refs       cpuset   fd       limits     mem         net 
        oom_score      personality  schedstat  smaps_rollup  status 
timerslack_ns
autogroup  cmdline          cwd      fdinfo   loginuid   mountinfo   ns 
        oom_score_adj  projid_map   sessionid  stack         syscall 
uid_map
auxv       comm             environ  gid_map  map_files  mounts 
numa_maps  pagemap        root         setgroups  stat          task 
wchan
cgroup     coredump_filter  exe      io       maps       mountstats 
oom_adj    patch_state    sched        smaps      statm         timers 

pidof:
ls: /proc/26476
pidof:
ls: /proc/26476
pidof:
ls: /proc/26476
pidof:
ls: /proc/26476
pidof:
ls: /proc/26476
pidof:
ls: /proc/26476
pidof: 26476
ls: /proc/26476
pidof: 26476

So the /proc/26476 is there even when pidof doesn't see the process.

>> But there are almost always holes in the output further on, so it's
>> also slightly unreliable afterwards.
> 
> This is really wierd, given that pid is same: process is not restarted.
> 
>> #!/bin/bash
>>
>> set -eu
>>
>> systemctl restart apcupsd
> 
> Do you have receipe to reproduce issue on systemd-free box, so I can try
> to debug issue myself?

Unfortunately no, I only have access to machines with systemd :(
Does replacing "systemctl restart apcupsd" with "/etc/init.d/apcupsd" work?

I had assumed that the problem should be easily reproducible with any 
other recently-started process, but that is apparently not the case:

buster-server ~ # cat sleep.sh
#!/bin/bash

set -eu
sleep 2 &
START=$SECONDS

ps aux|grep sleep
while true
do
   echo -n "pidof: "
   pidof -s sleep || echo
   [ $((SECONDS - START)) -ge 2 ] && break
   sleep 0.01
done
ps aux|grep sleep

Output:

buster-server ~ # ./sleep.sh
root     26946  0.0  0.0   6980  3120 pts/3    S+   14:19   0:00 
/bin/bash ./sleep.sh
root     26947  0.0  0.0   5596   752 pts/3    S+   14:19   0:00 sleep 2
root     26949  0.0  0.0   6424   884 pts/3    S+   14:19   0:00 grep sleep
pidof: 26947
pidof: 26947
pidof: 26947
pidof: 26947
pidof: 26947
[no holes like with apcupsd...]
pidof: 26947
pidof: 26947
root     26946  1.5  0.0   7112  3376 pts/3    S+   14:19   0:00 
/bin/bash ./sleep.sh
root     26947  0.0  0.0   5596   752 pts/3    S+   14:19   0:00 sleep 2
root     27069  0.0  0.0   6424   884 pts/3    S+   14:19   0:00 grep sleep

Maybe systemd is somehow involved?

-- 
Mit freundlichen Grüßen
Martin von Wittich

IServ GmbH
Bültenweg 73
38106 Braunschweig

Telefon: 0531-2243666-0
Fax: 0531-2243666-9
E-Mail: info at iserv.eu
Internet: iserv.eu

USt-IdNr. DE265149425 | Amtsgericht Braunschweig | HRB 201822
Geschäftsführer: Benjamin Heindl, Martin Hüppe, Jörg Ludwig
Grundsätze zum Datenschutz: https://iserv.eu/privacy