Logging Problems at Startup [RESOLVED]

[ozboomer]

Howdy, all...

Consider my frugal installation of NON-PAE Slacko Puppy 5.6.4...

I have some 'logger' commands, as well as simple 'echo' commands in rc.local and a couple of files that rc.local call... but the logger commands and the echo strings are not appearing in the /var/log/messages file. They always did in every version of Puppy I'd used since before 4.x.

Here's my /etc/rc.d/rc.local:-

Code: Select all

logger -s -p user.info -t rc.sitestartup "Running local.rc..."

echo rc.local started
echo rc.local started > /root/STARTUP_LOCAL.txt

echo checking syslogd.. >> /root/STARTUP_LOCAL.txt
ps -Al | grep syslog >> /root/STARTUP_LOCAL.txt

echo rc.local calling rc.sitestartup >> /root/STARTUP_LOCAL.txt

. /etc/rc.d/rc.sitestartup

echo rc.local returned from rc.sitestartup >> /root/STARTUP_LOCAL.txt

echo rc.local calling rc.firewall >> /root/STARTUP_LOCAL.txt

if [ -x /etc/rc.d/rc.firewall ]; then
  /etc/rc.d/rc.firewall start
fi

echo rc.local returned from rc.firewall >> /root/STARTUP_LOCAL.txt

echo rc.local finished >> /root/STARTUP_LOCAL.txt

...and the /root/STARTUP_LOCAL.txt file it updates:-

Code: Select all

rc.local started
checking syslogd..
rc.local calling rc.sitestartup
rc.local returned from rc.sitestartup
rc.local calling rc.firewall
rc.local returned from rc.firewall
rc.local finished

After startup, if I simply type:-

Code: Select all

# logger TEST

..the string appears in the messages file, as expected:-

Code: Select all

Mar  2 02:35:51 hexad daemon.debug dhcpcd[7345]: wlan0: sending ARP announce (1 of 2), next in 2.00 seconds
Mar  2 02:35:53 hexad daemon.debug dhcpcd[7345]: wlan0: sending ARP announce (2 of 2)
Mar  1 14:40:00 hexad user.notice root: TEST

Note, of course, that all the other messages up to that one have the silly time problem we know about...

So what d'you think is going on here? The scripts are running... and they're producing the expected 'on disk' output... but the logging and echo things don't seem to be working.

I note that syslogd is (maybe) NOT running at the time rc.local is running... but it appears to be running at the START of /var/log/messages, viz:-

Code: Select all

Mar  2 03:04:51 hexad syslog.info syslogd started: BusyBox v1.21.0
Mar  2 03:04:51 hexad user.notice kernel: klogd started: BusyBox v1.21.0 (2013-02-18 15:57:06 WST)
Mar  2 03:04:51 hexad user.notice kernel: [    0.000000] Linux version 3.4.52 (root@main) (gcc version 4.7.1 (GCC) ) #1 SMP Wed Jul 10 10:53:04 EST 2013

...so what does THAT mean?! It restarts itself after startup and there's no record of it!?

The problems don't exist in Lucid 5.2.8, but they DO exist in Precise 5.5, Precise 5.7.1, Slacko 5.6 and Slacko 5.6.4.

I wonder what has changed?... It's the first time I've had (significant) troubles with moving to a new Puppy ...

[Karl Godt]

In earlier times syslogd and klogd were started from rc.sysinit directly.

Now these are started by rc.services .

I still start them by rc.sysinit and even earlier before LOADING KERNEL MODULES.

But since I have no problems I almost never look into /var/log/messages .
Sporadically I look into /tmp/bootsysinit.log .

Busybox itself compiles quite fast and nicely to some full featured 2MB static binary . Probably worth a try to configure a full featured busybox of newer and older versions .

[ozboomer]

Hi again..

Many thanks for the info... and the reminder about /tmp/bootsysinit.log, which I'd totally forgotten about...

Well, I've had some joy... and it seems the script to use is /etc/init.d/00sys_logger, which is being called in a couple of places, it seems...

In my situation, I've placed a call to 00sys_logger in rc.sysinit, just prior to the "LOADING KERNEL MODULES" section, as was suggested... and things seem substantially Ok.

However, to help analyze all this, I added the following lines to the start of sys00_logger:-

Code: Select all

echo "00sys_logger: I was called '$0 $@'"
echo "00sys_logger: My parent was called: $(cat /proc/$PPID/cmdline)"

...the result of which was that I see where rc.sysinit calls it (an extract of /tmp/bootsysinit.log):-

Code: Select all

VERSION UPDATE
00sys_logger: I was called '/etc/rc.d/rc.sysinit start'
00sys_logger: My parent was called: /bin/busyboxinit
LOAD KERNEL MODULES

...but there's also the 'original' call, which I can't seem to find at all:-

Code: Select all

rc.local: rc.local Completed.
rc.sysinit: Exiting...
00sys_logger: I was called '/etc/init.d/00sys_logger start'
00sys_logger: My parent was called: /bin/ash/etc/rc.d/rc.services

(I added a simple 'echo' command to the end of rc.sysinit) I'm guessing it's in the 'frugal' initrd.gz or somthing...

So, all I can say is that there is something SOMEHWERE that has a copy of rc.services... and it's HERE that 00sys_logger is called... but the script at /etc/rc.d/rc.services doesn't seem to call 00sys_logger directly... *shrug*

The only problem is that I end-up with 2 syslogd and 2 klogd processes running.

Unless I can do something about the 2nd invocation of sys00_logger, I might just have to modify /etc/init.d/00sys_logger to immediately exit if we're in startup (how?)... and work normally otherwise...

..but this seems to be getting kinda complicated... hmm.....

[Karl Godt]

pidof command might come handy:

Code: Select all

pidof syslogd || syslogd
pidof klogd || klogd

[ozboomer]

pidof command might come handy:

Code: Select all

pidof syslogd || syslogd
pidof klogd || klogd

Heh... excellent thought.. but I've already reached a 'destination' via a slightly different route...

So, here's what I ended-up doing...

I updated 00sys_logger so that it will only start syslogd/klogd if they aren't already running. If a process IS running, it's restarted -- hopefully, this won't leave any wreckage about related to the statup time of the process being weird.

Anyway, here's the updated file:-

Code: Select all

#!/bin/sh

case $1 in
   start)
      ps -Al | grep syslogd > /dev/null
      if [ $? -eq 0 ];then
         killall syslogd
      fi
      sleep 2
      syslogd -m 0

      ps -Al | grep klogd > /dev/null
      if [ $? -eq 0 ];then
         killall klogd
      fi
      sleep 2
      klogd
      ;;
   stop)
      killall klogd
      killall syslogd
      ;;
esac

As always, Puppy (in ALL his variations) is a work in progress...

Many thanks for the kickstarts...

[npierce]

I see you have already come up with a good solution to your problem. I'll just add a little info here in hopes of clearing up some confusion.

Code: Select all

00sys_logger: My parent was called: /bin/ash/etc/rc.d/rc.services 

... but the script at /etc/rc.d/rc.services doesn't seem to call 00sys_logger directly... *shrug*

Actually, your echo command is quite correct: /etc/rc.d/rc.services does call 00sys_logger directly.

Don't be confused by the fact that the name "00sys_logger" doesn't appear in /etc/rc.d/rc.services. That script simply calls all executable files in the /etc/init.d/ directory:

Code: Select all

for service_script in /etc/init.d/*
do
 [ -x $service_script ] && $service_script start
done
unset service_script

And don't be confused by the fact that the call doesn't happen until after rc.sysinit exits. Notice that rc.sysinit executes rc.services in the background, so rc.sysinit can continue on its merry way and may finish before rc.services finishes:

Code: Select all

/etc/rc.d/rc.services & #run scripts in /etc/rc.d/init.d

By the way, if you want to eliminate the "the silly time problem we know about... ", you might try an experiment by uncommenting this line in /etc/rc.d/rc.sysinit:

Code: Select all

#unset TZ #100319 busybox hwclock gives priority to this (rather than /etc/localtime) and 'init' has set it wrong

So that it looks like this:

Code: Select all

unset TZ #100319 busybox hwclock gives priority to this (rather than /etc/localtime) and 'init' has set it wrong

I've not tried this. It might not work. And it might have side effects. So I make no guarantees.

[ozboomer]

Oooo, some good clues there... and I missed the background processes, etc 'coz I only had a half-hearted check through rc.services, rc.sysinit, etc - I admit it

Thanks a heap for the extra info...

[npierce]

You're welcome.