[Pkg-sysvinit-devel] sysv-rc: Multiple execution of rc2

[Michael]

Hi all,

I tracked this issue a little further...

But let's start with the beginning. I wanted to setup some custom boot tasks in /etc/rc.local, which is said to be the right place for it. However, it appeared this script is executed twice when booting into runlevel 2. And not only rc.local -- it's the whole rc2 which gets executed (at least) twice.

It's a Debian Sid system, daily updated, amd64 stock kernel, and nothing special installed (i hope).

I hacked a little 'tracker' script which is called by rc.local as well as a custom link from /etc/rc2.d/S00tracker. The baseline of this script is to print some process environment to a logfile.
(All logfiles and the fulls cript are attached to this mail as a tarball)

basically, 

echo "Runlevel: $RUNLEVEL"
echo "PPID: " $PPID
ps e -p $PPID
pstree
ps aux

This may be kind of overkill, but i wanted to ensure i don't miss some detail.

Now, this is the output of /etc/rc2.d/S00tracker written to a logfile in /tmp, right after booting into runlevel 2 (booting only into a login on textconsole, with X session disabled). Note the script is only appending anything (no initialization because that's already done by cleaning /tmp)  and you can  see anything appearing twice. Note the timestamps, there are a few seconds distance.
I'll cut the full process list -- the full output is appendet in the tarball.

Output excerpt:

--------- Time: 08:17:39 - rc2-S00 start ---------

Runlevel: 2
PPID:  1835

process environment:
  PID TTY      STAT   TIME COMMAND
 1835 ?        Ss     0:00 /bin/sh /etc/init.d/rc 2 HOME=/ init=/sbin/init TERM=linux BOOT_IMAGE=/boot/vmlinuz-2.6.30-2-amd64 PATH=/sbin:/usr/sbin:/bin:/usr/bin PWD=/ rootmnt=/root SELINUX_INIT=YES RUNLEVEL=2 PREVLEVEL=N CONSOLE=/dev/console INIT_VERSION=sysvinit-2.86

process tree:
init-+-portmap
     |-rc---S00tracker---S00tracker---pstree
     |-rpc.idmapd
     `-udevd---100*[udevd]

All processes:
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  4.2  0.0  10328   756 ?        Ss   08:17   0:00 init [2] 
(...)
root       816  0.7  0.0  17180  1428 ?        S<s  08:17   0:00 udevd --daemon
(this is appearing for 100 lines here !)
root      1835  0.0  0.0  17616  1692 ?        Ss   08:17   0:00 /bin/sh /etc/init.d/rc 2
root      1837  0.0  0.0  17424  1408 ?        S    08:17   0:00 /bin/sh -e /etc/rc2.d/S00tracker start
root      1839  0.0  0.0  17424   740 ?        S    08:17   0:00 /bin/sh -e /etc/rc2.d/S00tracker start
root      1842  0.0  0.0  14744  1012 ?        R    08:17   0:00 ps aux

----------- rc2-S00 stop -----------

--------- Time: 08:17:45 - rc2-S00 start ---------

Runlevel: 2
PPID:  1835

process environment:
  PID TTY      STAT   TIME COMMAND
 1835 ?        Ss     0:00 /bin/sh /etc/init.d/rc 2 HOME=/ init=/sbin/init TERM=linux BOOT_IMAGE=/boot/vmlinuz-2.6.30-2-amd64 PATH=/sbin:/usr/sbin:/bin:/usr/bin PWD=/ rootmnt=/root SELINUX_INIT=YES RUNLEVEL=2 PREVLEVEL=N CONSOLE=/dev/console INIT_VERSION=sysvinit-2.86

process tree:
init-+-acpid
     |-atd
     |-avahi-daemon---avahi-daemon
     |-console-kit-dae---63*[{console-kit-dae}]
     |-cron
     |-cupsd
     |-2*[daemon---less]
     |-dbus-daemon
     |-gpm
     |-hald---hald-runner-+-hald-addon-acpi
     |                    |-hald-addon-cpuf
     |                    |-hald-addon-inpu
     |                    `-hald-addon-stor
     |-portmap
     |-rc---S00tracker---S00tracker---pstree
     |-rpc.idmapd
     |-rpc.mountd
     |-syslog-ng
     |-udevd---2*[udevd]
     `-xinetd

All processes:
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  2.7  0.0  10328   756 ?        Ss   08:17   0:00 init [2]  
root       816  0.4  0.0  17180  1432 ?        S<s  08:17   0:00 udevd --daemon
(udev only 3 times now)
root      1835  0.7  0.0  17644  1720 ?        Ss   08:17   0:00 /bin/sh /etc/init.d/rc 2
(...)
root      1896  0.5  0.0  19596   940 ?        Ss   08:17   0:00 /usr/sbin/syslog-ng -p /var/run/syslog-ng.pid
root      1907  0.0  0.0   3828   556 ?        Ss   08:17   0:00 /usr/sbin/acpid
104       1917  0.1  0.0  23332   928 ?        Ss   08:17   0:00 /usr/bin/dbus-daemon --system
avahi     1928  0.1  0.0  33808  1520 ?        S    08:17   0:00 avahi-daemon: running [gandalf.local]
avahi     1929  0.0  0.0  33680   524 ?        Ss   08:17   0:00 avahi-daemon: chroot helper
root      1961  0.4  0.0 115860  2832 ?        Ssl  08:17   0:00 /usr/sbin/console-kit-daemon
(...)
root      2339  0.0  0.0  17424  1404 ?        S    08:17   0:00 /bin/sh -e /etc/rc2.d/S00tracker start
root      2341  0.0  0.0  17424   736 ?        S    08:17   0:00 /bin/sh -e /etc/rc2.d/S00tracker start
root      2344  0.0  0.0  14744  1016 ?        R    08:17   0:00 ps aux

----------- rc2-S00 stop -----------

I have some questions:

(1) What does the '2' in the 'init [2]' entry of the ps output mean ?

(2) Why does udev launch 100 processes ? Is this normal ??

(3) What does SELINUX_INIT=YES (in the process environment) mean ? Package SeLinux is not installed here!

(4) When the script had another desing, before, i could see 63 * console-kit at boot time. I guess the processes are launched and terminated again so quickly that the 'ps' snapshot is variable. 


I can see some essential services FAIL (syslog, cron and xientd). But apparently they are just running later. I suspect it's because some redundant init process tries to start them twice. 

However, i can not find these FAIL messages in any log in /var/log (for example, not with grep -r FAIL *, nor when i grep for the service name).

I am also a little bit irritated about to how get the boot messages from the runlevel initscripts stored on disk, for later analysis. 

Further infos:
- The sysv-rc and sysvinit packages are version 2.87dsf-8.
- /etc/inittab is the original default one (i reinstalled sysvinit).
- It's still the legacy runlevel init setup.

Explanation:
I rejected the upgrade to the new dependency system in about October, since some initsripts were not properly prepared that time; later, when this was resolved, i already noted this weird bug and i still did not do it because i wanted to track this problem first. 
The indicator file '/etc/init.d/.legacy-bootordering' is in place and works :)

- I noted the problem only after the upgrade to grub2, but this may as well be unrelated.

Attached files:

rc2-S00 .... log output of /etc/rc2.d/S00tracker (this is a symlink to the actual script)
rclocal  ..... log output of rc.local (invoking the tracker script)
tracker ..... the tracker script
systemlogs .... some default logs. Note i cleared the system logs before reboot so all entries are from one boot process. Actually i created these files 2 days in the past but nothing changed since then.

I would appreciate any idea how to track this problem down. It does not keep me from doing my work, it's just i'm worried what else may be screwed. I somehow can not trust this system anymore.
I even started to wonder if it could be a virus (although i never heard of any linux PC virus) !

Maybe the problem would be 'solved' by upgrading to the new dependency system. However, it should be tracked right now, because it never should have happened in the first place, and i believe we need to know how it is possible. Because problems that disappear magically, tend to re-appear magically, suddenly, some day.

ps. if you think it's worth with the available data, ATM, i'm ready to file a bug. But i hope you've got some ideas how to track it better than i could do, and i can file a bug much more to the point then. 



-------------- next part --------------
A non-text attachment was scrubbed...
Name: 2009-12-04.tar.bz2
Type: application/x-bzip
Size: 26230 bytes
Desc: not available
URL: <http://lists.alioth.debian.org/pipermail/pkg-sysvinit-devel/attachments/20091204/2421d1e1/attachment-0001.bin>