During my daily sysadmin tasks I've been contacted by a colleague, reporting issues with missing logs in rsyslog on a very old Redhat Server release 5.11.
Exact version is:
root@linux-server:~# cat /etc/redhat-release
Red Hat Enterprise Linux Server release 5.11 (Tikanga)
After checking the logs, I have confirmed his finding that in reality since about more than a year logs were not produced and al I could find multiple messages in /var/log/messages reading like:
init: Id "ad" respawning too fast: disabled for 5 minutes
init: Id "ad" respawning too fast: disabled for 5 minutes
init: Id "ad" respawning too fast: disabled for 5 minutes
init: Id "ad" respawning too fast: disabled for 5 minutes
init: Id "ad" respawning too fast: disabled for 5 minutes
init: Id "ad" respawning too fast: disabled for 5 minutes
…
I've checked the status of rsyslog which seemed to be fine
root@linux-server:~# /etc/init.d/rsyslog status
rsyslogd (pid 13709) is running…
The redhat version on the system was
root@linux-server:~# rpm -qa |grep -i rsyslog
rsyslog-3.22.1-7.el5
root@linux-server:~# tail -n 16 /var/log/messages
Apr 15 17:21:25 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 17:26:26 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 17:31:27 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 17:36:28 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 17:41:29 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 17:46:30 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 17:51:31 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 17:56:32 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 18:01:33 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 18:06:34 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 18:11:35 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 18:16:38 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 18:21:39 linux-server init: Id "ad" respawning too fast: disabled for 5 minutes
root@linux-server:~# /etc/init.d/rsyslog status
rsyslogd (pid 13709) is running…
Since the system is so old and I've seen this message and experienced this "respawning too fast: disabled for 5 minutes" myself in the past on some old Redhat 6.0 before RHEL was born as well as on Slackware Linux. The /etc/inittab which is nowadays obsoleted in newer Linux distributions was used to keep respawing a processes which have the chance to die out for some reason.
For those unfamiliar with inittab there is a short extract from man inittab to get idea what it is.
NAME
inittab – format of the inittab file used by the sysv-compatible init
process
DESCRIPTION
The inittab file describes which processes are started at bootup and
during normal operation (e.g. /etc/init.d/boot, /etc/init.d/rc, get-
tys…). Init(8) distinguishes multiple runlevels, each of which can
have its own set of processes that are started. Valid runlevels are
0-6 plus A, B, and C for ondemand entries. An entry in the inittab
file has the following format:
id:runlevels:action:process
So for example the use of /etc/inittab was very handy to configure a separate TTY12 (physical console) in the text environment of Linux to log all your messages. Another good use if you had a bash / perl / python script that you wanted to respawn (resurrect itself if it does out) on OS level without adding additional software like Dan Bernstein's all famous daemontools inittab was the right thing to use. It is a pity nowadays inittab is obsoleted in modern Linux OSes but the most likely reason to remove it is if you put some broken script that overeats CPU or memory if it runs multiple times you can easily get into a hung system.
Thus the logical thing to do is to check /etc/inittab content for any strange issues with less /etc/inittab and near the end of file found the problematic process which was triggering a never ending error messages to rsyslog and the module to protect from such messages in rsyslog by values $SystemLogRateLimitInterval and $SystemLogRateLimitBurst
# configure rsyslog rate limiting
# Rate-limiting
$SystemLogRateLimitInterval 5
$SystemLogRateLimitBurst 50000
The problem causing respawning too fast: disabled for 5 minutes
Was an old version of TivSM IBM Tivoli Service Manager /opt/tivoli/tsm/client/ba/bin/dsmc, set in the past in /etc/inittab it seems some colleague after updating to a more recent version has either changed the location of dsmc binary either the architecture of old tsm itself required a record in /etc/inittab in case if for some reasons or bugs the dsmc during backup creation was dying.
root@linux-server:~# tail -8 /etc/inittab
6:2345:respawn:/sbin/mingetty tty6# Run xdm in runlevel 5
x:5:respawn:/etc/X11/prefdm -nodaemon#ad:2345:respawn:/opt/tivoli/tsm/client/ba/bin/dsmc sched >/dev/null 2>&1
root@linux-server:~# rpm -qa |grep -i tivsm
TIVsm-API-5.3.4-0
TIVsm-stagent-5.3.4-0
TIVsm-BA-5.3.4-0
TIVsm-API64-5.3.4-0
The logical thing to do was to check whether this binary exist at all here is the result:
root@linux-server:~$ ls -al /opt/tivoli/tsm/client/ba/bin/dsmc
ls: /opt/tivoli/tsm/client/ba/bin/dsmc: No such file or directory
Obviously someone decided to comment out the inittab support for /opt/tivoli/tsm/client/ba/bin/dsmc as the binary was not present and the dsmc backup was executed via a separate one time cron job or the service itself was configured to run continue, but forgot to reread its configuration so in the kernel memory inittab was still having the instruction to loop over the dsmc binary, since the Linux machine was not rebooted ages (1472 days) or 4.8 years time.
root@linux-server:~# uname -a; echo; uptime
Linux linux-server2.6.18-419.el5 #1 SMP Wed Feb 22 22:40:57 EST 2017 x86_64 x86_64 x86_64 GNU/Linux19:04:34 up 1472 days, 5:20, 1 user, load average: 0.12, 0.07, 0.06
So what really happens is <b>inittab</b> is trying to kind of re-run all the time dsmc process in a similar way like it would in a bash never ending loop;
while [ 1 ]; do
/opt/tivoli/tsm/client/ba/bin/dsmc sched
done
Since the $PATH location to the binary returns 'No such file or directory' message this message floods up the rsyslog every second which triggers the LimitBurst protection of rsyslog causing rsyslog to disable completely logging for 5 minutes. The next 5 minutes when the time expires for blocking out logging due to reached limit burst.
dsmc binary sends again few ten thousand of messages for few seconds which are already waiting in a queue of rsyslog and the LimitBurst anti DDoS protection activates again. The reason for the LimitBurst is simply because if it logging is not disabled quickly the repeating message is going to fill the hard drive of the system and noone will be able to login. So rsyslog activated the good protection.
It seems noone from support colleagues, never ever noticed this init: Id "ad" respawning too fast: disabled for 5 minutes in /var/log/messages. So since the syslog was continuesly blocked by overflow of non-sense messages, systems normal logging was interruped and respectively prevented any other meaningful error messages and warnings from the system to get properly logged and perhaps flooed the remote rsyslog logging servers @logging-servers:514 in /etc/rsyslog.conf …
Fix to respawning too fast: disabled for 5 minutes
Very simply make /etc/inittab get reloaded in memory with:
root@linux-server:~# /sbin/init q
or with the linked telnet, which was so much used by us sys admins in the past
root@linux-server:~# /sbin/telinit q
To make the rsyslog suspension disabled of course we need to restart it again.
root@linux-server:~# /etc/init.d/rsyslog restart
root@linux-server:~# /etc/init.d/rsyslog status
rsyslogd (pid 13710) is running…
And Voila logs from services are being delivered normally via configured stuff in /etc/rsyslog.conf, to make sure this is so:
root@linux-server:~# tail -8 /var/log/messages
Apr 15 14:36:29 linux-serverinit: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 14:41:37 linux-serverinit: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 14:51:22 linux-serverinit: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 14:56:30 linux-serverinit: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 15:01:38 linux-serverinit: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 15:06:45 linux-serverinit: Id "ad" respawning too fast: disabled for 5 minutes
Apr 15 18:21:49 linux-server init: Re-reading inittab
Apr 15 18:21:54 linux-server kernel: imklog 3.22.1, log source = /proc/kmsg started.
Apr 15 18:21:54 linux-server rsyslogd: [origin software=”rsyslogd” swVersion=”3.22.1″ x-pid=”13709″ x-info=”http://www.rsyslog.com”] (re)start
Apr 15 18:41:54 linux-server rsyslogd: — MARK —
Apr 15 19:01:54 linux-server rsyslogd: — MARK —
Apr 15 19:21:54 linux-server rsyslogd: — MARK —
Apr 15 19:41:54 linux-server rsyslogd: — MARK —
Apr 15 20:01:54 linux-server rsyslogd: — MARK —