[ Main | Local ]

Normalerweise ist es ja so, daß man das Syslog benutzt, um andere Dienste zu debuggen. Ab und an kommt es aber vor, daß das Syslog als solches debuggt werden muß.

Hier in diesem Beispiel dreht es sich um eine Anwendung (Firewall), die ins Syslog loggt, also die vorgefertigte Nachricht mit Angaben zu Priorität etc. an das Syslog gibt. Eigenartigerweise ließen sich diese Nachricht nicht entsprechend ihrer Prioritäten unterdrücken - und die Firewall-Leute sagen, sie seien unschuldig.

Also wurde der Syslog-Deamon im Debug-Mode gestartet, er schreibt dann alles auf die Konsole. Die Konsole kann man setzten (wo sie steht zeigt unter AIX der Befehl lscons).

Im einfachsten Fall sollte soetwas gehen:

/usr/sbin/syslogd -d
oder so:
/etc/syslogd -d 2>&1 >/tmp/syslog.debug &

Mit AIX kann man es sich ein bischen umständlicher machen:
stopsrc -s syslogd
chssys -s syslogd -a "-d"
startsrc -s syslogd
lssrc -ls syslogd

Man kann dann mit dem lssrc-Befehl den Status des syslog-Deamons abfragen:

 
root@FW:/ # lssrc -ls syslogd
Subsystem         Group            PID     Status
 syslogd          ras              7560    active

Syslogd Config   local4.error  /var/log/firewall.log
Syslogd Config   daemon.notice /var/adm/SPlogs/SPdaemon.log
Syslogd Config   local0.crit /usr/es/adm/cluster.log
Syslogd Config   local0.info /usr/es/adm/cluster.log
Syslogd Config   user.notice /usr/es/adm/cluster.log

Wenn man zuende getestet hat, dann sollte man alles wieder zurücksetzten und prüfen, ob das geklappt hat:
chssys -s syslogd -a ""
odmget -q subsysname=syslogd SRCsubsys
stopsrc -s syslogd
startsrc -s syslogd

Man sollte daran denken, daß im Debug-Mode nicht alle Events geloggt werden. Timemarks z.b. werden nicht mitgeloggt. Wichtig ist auch, das in der Ausgabe alle Events/Nachrichten auftauchen, auch diejenigen, die dann später verworfen werden.

Was vom Syslog dann zurückgegeben wird, sieht etwa so aus (von einem AIX System):

 
can't open /dev/klog (2)
off & running....
init
cfline(local4.error  /var/log/firewall.log)
cfline(daemon.notice /var/adm/SPlogs/SPdaemon.log)
cfline(local0.crit /usr/es/adm/cluster.log)
cfline(local0.info /usr/es/adm/cluster.log)
cfline(user.notice /usr/es/adm/cluster.log)
X X X X X X X X X X X X X X X X X X X X 3 X X X X FILE: /var/log/firewall.log
X X X 5 X X X X X X X X X X X X X X X X X X X X X FILE: /var/adm/SPlogs/SPdaemon.log
X X X X X X X X X X X X X X X X 2 X X X X X X X X FILE: /usr/es/adm/cluster.log
X X X X X X X X X X X X X X X X 6 X X X X X X X X FILE: /usr/es/adm/cluster.log
X 5 X X X X X X X X X X X X X X X X X X X X X X X FILE: /usr/es/adm/cluster.log
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 UNUSED:
logmsg: pri 56, flags 8, from speth05, msg syslogd: restart
syslogd: restarted
readfds = 0x2018
got a message (1, 0x8)
logmsg: pri 245, flags 0, from speth05, msg Feb 18 10:33:44 syslog: 2003;13198: 18141;ICA9070i;4;2;10:33:44;02-18-2003;
readfds = 0x2018
got a message (1, 0x8)
logmsg: pri 206, flags 0, from speth05, msg Feb 18 10:33:44 : root;fwStartFilterLog; cmd=startlog;rc=1
Logging to FILE /usr/es/adm/cluster.log
readfds = 0x2018
got a message (1, 0x8)
logmsg: pri 243, flags 0, from speth05, msg Feb 18 10:33:45 : 2003;15256: 2151;ICA1075i;1;505;506;1;p;i;217.6.210.36;217.6.210.37;10.10.30.7;udp;sp:;1645;dp:;1645;r;n;n;0;72;
Logging to FILE /var/log/firewall.log
readfds = 0x2018
got a message (1, 0x8)
logmsg: pri 245, flags 0, from speth05, msg Feb 18 10:34:13 syslog: 2003;14096: 18143;ICA9071i;10:34:13;02-18-2003;
readfds = 0x2018
got a message (1, 0x8)
logmsg: pri 36, flags 0, from speth05, msg Feb 18 10:40:54 xntpd[8750]: offset -0.000087 freq 30.03317 comp 2
readfds = 0x2018
got a message (1, 0x8)
logmsg: pri 36, flags 0, from speth05, msg Feb 18 10:41:15 sshd[8524]: log: Generating new 768 bit RSA key.

 
X X X X X X X X X X X X X X X X X X X X 3 X X X X FILE: /var/log/firewall.log
X X X 5 X X X X X X X X X X X X X X X X X X X X X FILE: /var/adm/SPlogs/SPdaemon.log

Die Syslog-Matrix ist so zu verstehen:
Spalten sind die Facilities, nach der Nummerierung in syslog.h. Die Zahlen sind die Prioritäten, die in dieser Facility geloggt werden sollen. Die Zeilen sind ein Ausgabe-Kanal, also ein File, User oder die Console.

Syslog kennt eine Reihe Facilities, also Typen von Nachrichten, die er loggen kann (Mail, Kernel, Authentication etc.). Jede dieser Facilities hat eine Priorität (debug, warn etc). Bezüglich des Loggings gibt es Kanäle, also wohin geschrieben werden soll.

Obiges Beispiel einer Matrix bedeuten also: Die 21. Spalte ist die Facility 20 (wir fangen mit 0 zu zählen an), also LOCAL4, eine Facility, die der User definieren kann. Alle Nachrichten mit Level 3 (error) und höher werden nach /var/log/firewall.log geschrieben - das ist ein File.

Die nötigen Informationen kommen aus dem entsprechenden Header-File /usr/include/sys/syslog.h:

 
/*  Facility codes */

#define LOG_KERN	(0<<3)	/* kernel messages */
#define LOG_USER	(1<<3)	/* random user-level messages */
#define LOG_MAIL	(2<<3)	/* mail system */
#define LOG_DAEMON	(3<<3)	/* system daemons */
#define LOG_AUTH	(4<<3)	/* security/authorization messages */
#define LOG_SYSLOG	(5<<3)	/* messages generated internally by syslogd */
#define LOG_LPR		(6<<3)	/* line printer subsystem */
#define LOG_NEWS	(7<<3)	/* news subsystem */
#define LOG_UUCP	(8<<3)	/* uucp subsystem */
#define LOG_CRON	(9<<3)	/* clock daemon */
	/* other codes through 15 reserved for system use */
#define LOG_LOCAL0	(16<<3)	/* reserved for local use */
#define LOG_LOCAL1	(17<<3)	/* reserved for local use */
#define LOG_LOCAL2	(18<<3)	/* reserved for local use */
#define LOG_LOCAL3	(19<<3)	/* reserved for local use */
#define LOG_LOCAL4	(20<<3)	/* reserved for local use */
#define LOG_LOCAL5	(21<<3)	/* reserved for local use */
#define LOG_LOCAL6	(22<<3)	/* reserved for local use */
#define LOG_LOCAL7	(23<<3)	/* reserved for local use */


 /*  Priorities (these are ordered) */

#define LOG_EMERG	0	/* system is unusable */
#define LOG_ALERT	1	/* action must be taken immediately */
#define LOG_CRIT	2	/* critical conditions */
#define LOG_ERR		3	/* error conditions */
#define LOG_WARNING	4	/* warning conditions */
#define LOG_NOTICE	5	/* normal but signification condition */
#define LOG_INFO	6	/* informational */
#define LOG_DEBUG	7	/* debug-level messages */

Die Notation (9<<3) bedeutet, daß der betrachtete Wert um 3 Bit nach Links verschoben wird, und das Ergebnis 9 sein muß (also der verbliebene Rest). Diese 3 Bit sind dann der Wert der Priorität.

Nach der Matrix schreibt der Syslogd alle Messages raus, die herein kommen. Er liest das System-Errorlog Device (je nach Unix ist das z.b. /dev/logfifo, /dev/log etc.) - der Syslogd gibt den zugehörigen Filedescriptor an (readfds = 0x2018). Danach kommt die vom Deamon gesendete Nachricht. Diese wird unverändert übernommen, interessant ist die Angabe pri xxx. Dann folgt, was mit der Nachricht passiert ist. Die Zeile Logging to FILE zeigt an, daß diese Nachricht effektiv geloggt wurde. Fehlt diese Zeile, so wurde die Nachricht verworfen.

 
readfds = 0x2018
got a message (1, 0x8)
logmsg: pri 243, flags 0, from speth05, msg Feb 18 10:33:45 : 2003;15256: 2151;ICA1075i;1;505;506;1;p;i;217.6.210.36;217.6.210.37;10.10.30.7;udp;sp:;1645;dp:;1645;r;n;n;0;72;
Logging to FILE /var/log/firewall.log

Das pri xxx Feld ist ein Oktal-Wert. Den überführt man mit dem bc in Binär, und erhält das Register für die Werte. Hier ein paar Beispiele:

 
root@FW:/ # bc
obase=2
ibase=8
25
10101

Also 00010101, 3 Bit nach Rechts: 00000010, also Dezimal 2. Facility ist also 2 (mail).

In 00010101 sind die letzten 3 Bit gleich 101, also dezimal 5. Priority ist also 5 (notice).

In diesem Sinne mit den anderen Zahlen des Beispiels:

 
206
10000110

Facility: 16 (local0)
Priority: 6 (info)

243
10100011

Facility: 20 (local4)
Priority: 3 (error)

245
10100101

Facility: 20 (local4)
Priority: 5 (notice)

36
11110

Facility: 3 (daemon)
Priority: 6 (info)

In unserem Fall wird also eine Nachricht, die die Firewall als Info einstuft, dem Syslog mit Priority Error übergeben - damit war für uns klar, daß hier der Firewall-Programmierer nicht richtig verstanden hatte, was er tut.

Auf Nachfrage beim Support stellte sich dann heraus, daß einmal die Prioritäten von Firewall und Syslog nicht genau gleich sind und zum anderen verschiedene Meldungen der Firewall unabhänging von der Priorität nicht vom Syslog unterdrückt werden sollen - daher wird in einem solchen Fall die Priorität zwar mit informational angegeben, aber dann effektiv höher geflaggt. Das ist natürlich nicht dokumentiert.

Weitere praktische Dinge, die sich im Zug der Analyse gefunden haben:

Mit logger kann man selber ins Syslog schreiben:
logger -p user.local4 "mein Text"

Man kann auch direkt auf das Device schreiben:
echo "<135> Mein_Prozess failed " >/dev/logfifo (AIX wohl /dev/log)

Man errechnet die Zahl, die die Priorität und die Facility dem Syslog mitteilt, folgendermassen:

facility * 8 + priority

(20*8+3) = 163

Das widerspricht dem, was weiter oben steht - binär ist es aber gleich...

 
root@FW:/ # bc
obase=2
163
10100011

243
10100011

Dann gibt es noch einen String (%m), der auf die Errornummer gesetzt ist (aus /usr/include/errno.h):

logger -p local0.debug "Mein_Prozeß failed. Grund: %m"

Mit -t kann man einen Tag mitgeben, also z.b. den Namen des Prozeßes etc.; mit -f kann man einen Message-Text ausgeben:
logger -p local0.notice -t ADMIN -f /usr/msg/Meine_Message

[ Main | Local ]

[ Allgemein | UNIX | AIX | TCP-IP | TCP | ROUTING | DNS | NTP | NFS | FreeBSD | Linux | RPi | SMTP | Tracing | GPS | LW ]