csl - colour syslog lines
One of our customers makes heavy use of syslog in his data centre. There are internal and external gateways running several services, e.g. bind DNS, exim for e-mail, some proxies (see www.quietsche-entchen.de. Especially the proxies like to write things to syslog for the little things they do or deny. And since there are so many gateways, there is also a central syslog server, one hosts getting all the syslog stuff from the others. This setup makes it easy to monitor what's going on in the network.
Now when you try to "tail -f" the central logfile, the lines don't scroll, they jump across the screen. It's far too quick to see anything (even in an X console with a large screen). A colleague mentioned to put the logfile through a log colouriser, this would make life a bit easier and he also mentioned a program for it. He installed it but I wasn't that impressed, I thought that this is nothing I couldn't do with a short awk script. Get the full csl script here.
syslog file format
Just in case you don't how syslog lines look, here is a short extract:
1 Jan 23 06:35:33 my-server syslogd 1.4.1#17: restart. 2 Jan 23 06:36:32 my-server CRON[8876]: (pam_unix) session closed for user root 3 Jan 23 06:38:01 my-server CRON[9258]: (pam_unix) session opened for user mail by (uid=0) 4 Jan 23 06:38:01 my-server /USR/SBIN/CRON[9259]: (mail) CMD ( if [ -x /usr/sbin/exim -a -f /etc/exim/exim.conf ]; then /usr/sbin/exim -q ; fi) 5 Jan 23 06:38:01 my-server CRON[9258]: (pam_unix) session closed for user mail 6 Jan 23 06:39:01 my-server CRON[9270]: (pam_unix) session opened for user root by (uid=0) 7 Jan 23 06:39:01 my-server CRON[9270]: (pam_unix) session closed for user root 8 Jan 23 06:39:42 my-server smtp.proxy[9286]: connected to client: aa.bb.cc.dd 9 Jan 23 06:39:42 my-server smtp.proxy[9286]: +INFO: rbl match, server= sbl-xbl.spamhaus.org, ipnum= aa.bb.cc.dd, TXT= http://www.spamhaus.org/query/bl?ip=aa.bb.cc.dd 10 Jan 23 06:39:42 my-server smtp.proxy[9286]: +OK: client aa.bb.cc.dd disconnecting, 0 mails 11 Jan 23 06:42:49 my-server smtp.proxy[9310]: connected to client: a2.b2.c2.d2 12 Jan 23 06:42:49 my-server smtp.proxy[9310]: +INFO: rbl match, server= sbl-xbl.spamhaus.org, ipnum= a2.b2.c2.d2, TXT= http://www.spamhaus.org/query/bl?ip=a2.b2.c2.d2 13 Jan 23 06:42:53 my-server smtp.proxy[9310]: +INFO: rbl match, server= dnsbl.sorbs.net, ipnum= a2.b2.c2.d2, TXT= Exploitable Server See: http://www.sorbs.net/lookup.shtml?a2.b2.c2.d2 14 Jan 23 06:42:53 my-server smtp.proxy[9310]: +OK: client a2.b2.c2.d2 disconnecting, 0 mails 15 Jan 23 06:44:01 my-server smtp.proxy[9315]: connected to client: a3.b3.c3.d3 16 Jan 23 06:44:01 my-server smtp.proxy[9315]: +INFO: rbl match, server= sbl-xbl.spamhaus.org, ipnum= a3.b3.c3.d3, TXT= http://www.spamhaus.org/query/bl?ip=a3.b3.c3.d3 17 Jan 23 06:44:01 my-server smtp.proxy[9315]: +INFO: rbl match, server= dnsbl.sorbs.net, ipnum= a3.b3.c3.d3, TXT= Exploitable Server See: http://www.sorbs.net/lookup.shtml?a3.b3.c3.d3 18 Jan 23 06:44:01 my-server smtp.proxy[9315]: +OK: client a3.b3.c3.d3 disconnecting, 0 mails 19 Jan 23 06:45:01 my-server CRON[9318]: (pam_unix) session opened for user nobody by (uid=0) 20 Jan 23 06:45:01 my-server /USR/SBIN/CRON[9319]: (nobody) CMD (test -f /var/www/scripts/reindex && /var/www/scripts/reindex) 21 Jan 23 06:45:01 my-server CRON[9318]: (pam_unix) session closed for user nobody 22 Jan 23 06:45:21 my-server smtp.proxy[9325]: connected to client: a4.b4.c4.d4 23 Jan 23 06:45:22 my-server smtp.proxy[9325]: +INFO: rbl match, server= sbl-xbl.spamhaus.org, ipnum= a4.b4.c4.d4, TXT= http://www.spamhaus.org/query/bl?ip=a4.b4.c4.d4 24 Jan 23 06:45:22 my-server smtp.proxy[9325]: +INFO: rbl match, server= dnsbl.sorbs.net, ipnum= a4.b4.c4.d4, TXT= Dynamic IP Addresses See: http://www.sorbs.net/lookup.shtml?a4.b4.c4.d4 25 Jan 23 06:45:22 my-server smtp.proxy[9325]: +OK: client xxx-xx-xx-xx-xx.example.com disconnecting, 0 mails
Of course I removed IP-numbers, names and so on from it. Nevertheless, what you see in the logfile is that the systems starts some cron job and smtp.proxy rejects several email clients because they are blacklisted - business as usual.
The format of each syslog line is
| Pos | Data | Comment |
| 1 | name of month | not the fullname, only an abbreviation (the usual English short name). |
| 2 | day of month | if it's only one digit, the first digit is not a zero, it's a blank. |
| 3 | system time | |
| 4 | hostname | the hostname, either the syslog host itself of the host that send the message. The hostname may |
| 5 | process name and pid | the name of the process that wrote the line with its process id. If there's the pid or not depends on the process, e.g. the syslog does not write its message with a pid (see line #1). |
| 6 | message | the rest of the line is the log message itself, the format depends of the program. |
The contents of the fields one to three is always the same, there are no surprises. The hostname is also simple to parse (if this is required at all); just cut away the domain name.
Adding some colours
The initial line processing is done by the following script code.
1
2 /./ {
3 date = sprintf ("%s %2s %s", $1, $2, $3);
4
5 host = tolower($4);
6 sub(/\..*$/, "", host);
7
8 if ((proc = tolower($5)) == "--" || proc == "last")
9 next;
10
11 sub(/.*\//, "", proc);
12 if (match(proc, /([^\[:]+)(\[([0-9]+)\])?/, x) > 0) {
13 proc = x[1];
14 pid = x[3];
15 }
16
Line #8 deals with two exception. If a progam writes a certain number of the same logline in a certain amount of time, syslog will not print every single line but a "last message repeated XX times" or similar. The other is that is syslog does not receive anything within a certain amount of time it will write a keep-alive message like "-- MARK --". Both exceptions are excluded by the next; in line #9.
Processing the process name starts in line #11. First any full pathname is removed (see cron's log entry in line #4 above). The following match() call matches always the proc value. The reason why I use match() is, that it returns the process name and the pid in the x argument.
The script continues with cutting the beginning of the line up to the first colon and the following white spaces.
1 line = substr($0, 16); 2 sub(/[^:]*:[ \t]*/, "", line);
This gives the actual log message in line.
1 chost = (host in colorhost)? __c6 __bold $4 __normal: __green __bold $4 __normal; 2 cproc = (proc in colorproc)? __yellow proc __normal: proc; 3 if (pid != "") 4 cproc = cproc "[" pid "]"; 5 6 if (markpattern != "" && match(host ":" proc, markpattern) != 0) 7 date = __yellow date __normal;
The next few things I do is
- colour the hostname different depending on if it is found in the
colorhostassociative array, - the same for the process name, and
- colour the logline's date in yellow if the line matches the pattern
markpattern.
Just accept the variables colorhost, colorproc and markpattern are set, we will come back to that later.
Next I check if the log message starts with a plus "+" or minus "-" followed by some letters and an optional colon.
1 if (match(line, /^[+-][a-z]+:?/) > 0) {
2 if (substr(line, 1, 1) == "-")
3 line = __red substr(line, 1, RLENGTH) __normal substr(line, RSTART+RLENGTH);
4 else if (substr(line, 1, RLENGTH) == "+OK:")
5 line = __green __bold substr(line, 1, RLENGTH) __normal substr(line, RSTART+RLENGTH);
6 else
7 line = __blue __bold substr(line, 1, RLENGTH) __normal substr(line, RSTART+RLENGTH);
8 }
This matches e.g. smtp.proxy's lines #9 and #10. If the line starts with +OK: it is colored green, everything else starting the a + gets blue and something starting with a - is coloured red. This way it is easy to notice (or catch) the most common (for my customer's data centre setup) error messages - even if they scroll very quick.
The script ends with
1 2 line = parsevalues(line); 3 print date, chost, cproc ":", line __normal; 4 } 5
and any additional script magic is in parsevalues().
The parsevalues() is also somewhat tailored to the most common type and format of the log entries. The function finds sequences of the type "NAME=VALUE" (from the kernel packet filter) and "name= value" (various proxies, sendmail) and colours
- the names grey,
- the value in bold yellow or red if the value's name is
error.
1
2 function parsevalues(string, arr, p, var, val, x) {
3 p = "";
4 if (match(string, /[A-Z]+=[^ ]/) > 0) {
5 # NAME=VAL
6 while (match(string, /([A-Z][A-Z0-9]*)=([^ ]*)( |$)/, x) > 0) {
7 p = p substr(string, 1, RSTART-1) __grey x[1] __normal "=" \
8 ((x[1] == "error")? __red: __yellow __bold) x[2] __normal x[3];
9 string = substr(string, RSTART+RLENGTH);
10 }
11 }
12 else {
13 # name= VAL,
14 while (match(string, /( +|^)([a-zA-Z][-\/a-zA-Z0-9]*)= ([^,]*)(, |$)/, x) > 0) {
15 p = p substr(string, 1, RSTART-1) x[1] __grey x[2] __normal "= " \
16 ((x[2] == "error")? __red: __yellow __bold) x[3] __normal x[4];
17 string = substr(string, RSTART+RLENGTH);
18 }
19 }
20
21 p = p string;
22 return (p);
23 }
24
The function is not perfect, the proxy/sendmail part is sometimes fooled by values that contain a comma (think of email message ids) but it does an overall good job.
Parsing command line options
The remaining things to do are
- initialising the colour sequences and
- reading any command line options.
Reading command line options is almost straight forward. Any arguments from the command line are in the ARGV[] array, ARGC is the upper index limit into ARGV[]. The thing to notice is that the values 1 to ARGC-1 are valid array elements (see line #31).
The other important thing is that if something is a command line option or argument, the array element must be cleared. Otherwise awk will interpret the argument as input file to the given script. This is done in the nextarg() function which also checks if a command line argument is available or not.
1
2 function nextarg(option, arg) {
3 if (argi >= ARGC) {
4 printf ("%s: missing argument: %s%s\n", program, (length(option) == 1? "-": ""), option);
5 exit (1);
6 }
7
8 arg = ARGV[argi];
9 ARGV[argi++] = "";
10
11 return (arg);
12 }
13
14 BEGIN {
15 program = "csl";
16
17 STDERR = "/dev/stderr";
18 IGNORECASE = 1;
19
20 __bold = "\033[01m";
21 __red = "\033[31m";
22 __green = "\033[32m";
23 __yellow = "\033[33m";
24 __blue = "\033[34m";
25 __c5 = "\033[35m";
26 __c6 = "\033[36m";
27 __grey = "\033[37m";
28 __normal = "\033[0m";
29
30 argi = 1;
31 while (argi < ARGC && substr(ARGV[argi], 1, 1) == "-") {
32 options = nextarg("option");
33 if (options == "--")
34 break;
35
36 for (i = 2; i<=length(options); i++) {
37 c = substr(options, i, 1);
38 if (c == "h") {
39 n = split(nextarg("hostlist"), x, /[ ,]+/);
40 for (i=1; i<=n; i++)
41 colorhost[x[i]] = 1;
42 }
43 else if (c == "p") {
44 n = split(nextarg("proclist"), x, /[ ,]+/);
45 for (i=1; i<=n; i++)
46 colorproc[x[i]] = 1;
47 }
48 else if (c == "g")
49 markpattern = nextarg("pattern");
50 else {
51 printf ("%s: unkown option: -%s\n", program, c)
52 exit (1);
53 }
54 }
55 }
56 }
57
csl accepts options to set the colorhost, colorproc and markpattern variables used later in the script.
Invocation:
csl [options] input-files ...
colour the line in input-files.
Command line options
- -h hostlist
-
a comma separated list of hostnames that are coloured special (default host color: green).
- -p proclist
-
a comma separated list of process names that are coloured yellow (default process colour: none).
- -g regexp
- lines matching regexp get their date information coloured yellow.
Any remaining arguments are used as input file names. The input fils are expected to be in syslog format.
Download the script (use your browser's "Save as ...").