Processing DHCP logs with AWK

On a recent project, I needed to run a performance test where tens of thousands of network devices communicate with a DHCP server. After the test, I wanted to create a pretty graph of the number of DHCP requests hitting the server.

DHCP requests per minute graph

Using a combination of AWK and Excel, I had a solution within half an hour…

The DHCP server writes events to a log file like this:

Aug  8 00:00:01 rchmms010 dhcpd: DHCPDISCOVER from 00:1d:ed:40:5f:b6 via 10.1.255.254
Aug  8 00:00:01 rchmms010 dhcpd: DHCPOFFER on 10.1.210.152 to 00:1d:ed:40:5f:b6 via 10.1.255.254
Aug  8 00:00:01 rchmms010 dhcpd: DHCPDISCOVER from 00:1d:ed:40:53:e8 via 10.1.255.254
Aug  8 00:00:01 rchmms010 dhcpd: DHCPOFFER on 10.1.239.99 to 00:1d:ed:40:53:e8 via 10.1.255.254
Aug  8 00:00:01 rchmms010 dhcpd: DHCPREQUEST for 10.1.239.99 (172.25.30.115) from 00:1d:ed:40:53:e8 via 10.1.255.254
Aug  8 00:00:01 rchmms010 dhcpd: DHCPACK on 10.1.239.99 to 00:1d:ed:40:53:e8 via 10.1.255.254
Aug  8 00:00:02 rchmms010 dhcpd: DHCPDISCOVER from 00:1d:ed:40:89:7d via 10.1.255.254
Aug  8 00:00:02 rchmms010 dhcpd: DHCPOFFER on 10.0.178.200 to 00:1d:ed:40:89:7d via 10.1.255.254
Aug  8 00:00:04 rchmms010 dhcpd: DHCPDISCOVER from 00:1d:ed:40:5f:b6 via 10.1.255.254
Aug  8 00:00:04 rchmms010 dhcpd: DHCPOFFER on 10.1.210.152 to 00:1d:ed:40:5f:b6 via 10.1.255.254
Aug  8 00:00:04 rchmms010 dhcpd: DHCPREQUEST for 10.1.210.152 (172.25.30.115) from 00:1d:ed:40:5f:b6 via 10.1.255.254
Aug  8 00:00:04 rchmms010 dhcpd: DHCPACK on 10.1.210.152 to 00:1d:ed:40:5f:b6 via 10.1.255.254
Aug  8 00:00:05 rchmms010 dhcpd: DHCPDISCOVER from 00:1d:ed:40:55:f4 via 10.1.255.254
Aug  8 00:00:05 rchmms010 dhcpd: DHCPOFFER on 10.0.187.211 to 00:1d:ed:40:55:f4 via 10.1.255.254
Aug  8 00:00:05 rchmms010 dhcpd: DHCPDISCOVER from 00:1d:ed:40:89:7d via 10.1.255.254
Aug  8 00:00:05 rchmms010 dhcpd: DHCPOFFER on 10.0.178.200 to 00:1d:ed:40:89:7d via 10.1.255.254
Aug  8 00:00:05 rchmms010 dhcpd: DHCPDISCOVER from 00:1d:ed:40:79:19 via 10.1.255.254
Aug  8 00:00:05 rchmms010 dhcpd: DHCPOFFER on 10.0.200.135 to 00:1d:ed:40:79:19 via 10.1.255.254
Aug  8 00:00:05 rchmms010 dhcpd: DHCPREQUEST for 10.0.178.200 (172.25.30.115) from 00:1d:ed:40:89:7d via 10.1.255.254
Aug  8 00:00:05 rchmms010 dhcpd: DHCPACK on 10.0.178.200 to 00:1d:ed:40:89:7d via 10.1.255.254

Obviously there are four message types: DHCPDISCOVER, DHCPOFFER, DHCPREQUEST, and DHCPACK. But the highly observant among you will have also noticed that the number of columns (space delimited) differs depending on the message type (DHCPDISCOVER=10, DHCPOFFER=12, DHCPREQUEST=13, DHCPACK=12).

Just to make things more difficult, there are occasional rows that have 11 and 15 columns.

1 2	Aug 8 00:10:46 rchmms010 dhcpd: uid lease 10.0.251.247 for client 00:1d:ed:40:2d:75 is duplicate on 10.0/15 Aug 8 00:30:58 rchmms010 dhcpd: Wrote 39312 leases to leases file.

The varying number of columns makes it impractical to process the logs using LogParser (which would have been a really neat solution), and the fact that the log file may have millions of rows means that Excel (by itself) is not the right tool either.

I wanted to aggregate the different types of request for each minute, and output a file for graphing in Excel. Writing a simple AWK program was a neat way to process the log file.

# This aggregates DHCP log files into types of request per minute.
# Types of request: DHCPDISCOVER, DHCPOFFER, DHCPREQUEST, DHCPACK
#
# Usage: gawk -f aggregate_dhcp.awk dhcp.log.1
#
# References: 
#    The GNU Awk User's Guide (http://www.gnu.org/manual/gawk/gawk.html)
#    Wikipedia: DHCP (http://en.wikipedia.org/wiki/Dynamic_Host_Configuration_Protocol)
 
BEGIN {
    FS = " " # fields in the input file must be separated by a space.
    OFS = "\t" # Output Field Separator is a tab.
 
    previousTime = ""
    previousDay = ""
    outputFile = "" # The file name will change depending on the date of the DHCP event in the log.
 
    # Keep a count of the different DHCP message types.
    numDhcpDiscover = 0
    numDhcpOffer = 0
    numDhcpRequest = 0
    numDhcpAck = 0
 
    print "Started processing DHCP log..."
}
 
# Do this for every line in the input file
{
    if ($6 == "DHCPDISCOVER") {
        numDhcpDiscover++
    } else if ($6 == "DHCPOFFER") {
        numDhcpOffer++
    } else if ($6 == "DHCPREQUEST") {
        numDhcpRequest++
    } else if ($6 == "DHCPACK") {
        numDhcpAck++
    } else {
        print $0 >> "errors.txt"
    }
 
    # Write a new header for each output file (1 output file for each day)
    currentDay = $2
    if (currentDay != previousDay) {
        outputFile = "DHCP_log_" $1 "_" $2 ".txt"
 
        # Time	DHCPDISCOVER	DHCPOFFER	DHCPREQUEST	DHCPACK
        print "Time", "DHCPDISCOVER", "DHCPOFFER", "DHCPREQUEST", "DHCPACK" >> outputFile
 
        previousDay = currentDay
    }
 
    currentTime = substr($3, 0, 5) # Convert hh:mm:ss to hh:mm
    if (currentTime != previousTime) {
        # Output format:
        # Time	DHCPDISCOVER	DHCPOFFER	DHCPREQUEST	DHCPACK
        print currentTime, numDhcpDiscover, numDhcpOffer, numDhcpRequest, numDhcpAck >> outputFile
 
        # Reset counters.
        numDhcpDiscover = 0
        numDhcpOffer = 0
        numDhcpRequest = 0
        numDhcpAck = 0
 
        previousTime = currentTime
    } 
}
 
END {
    print "Finished."
}

Here is the output of the AWK program (for the first 15 minutes of the DHCP server’s log file):

Time	DHCPDISCOVER	DHCPOFFER		DHCPREQUEST	DHCPACK
00:00	102	101	63	64
00:01	84	84	47	47
00:02	81	81	43	43
00:03	106	107	62	61
00:04	93	92	51	52
00:05	101	101	57	57
00:06	65	65	39	39
00:07	79	79	44	44
00:08	76	76	45	45
00:09	86	87	56	55
00:10	120	119	66	67
00:11	106	107	60	59
00:12	101	100	63	64
00:13	83	83	54	54
00:14	66	66	37	37
00:15	82	82	48	48

…and here are some example graphs:

Graph of DHCPDISCOVER messages per minute

Graph of DHCPOFFER messages per minute

Graph of DHCPREQUEST messages per minute

Graph of DHCPACK messages per minute

This entry was posted on Tuesday, August 10th, 2010 at 11:05 am and is filed under Other Tools.

3 Responses to “Processing DHCP logs with AWK”

Stuart Moncrieff says:

September 7, 2010 at 4:13 pm

Note that the graphs above are just from a normal day on the DHCP server, not from my actual performance test. :)

Reply
Chris says:

September 7, 2010 at 8:14 pm

Nice work Stu!!

Although I could have done it in less lines in Perl :-)

Reply
Jared says:

September 23, 2010 at 10:53 pm

I’m sure you could write it in less lines of Perl, but would anybody be able to read it? ;)

Awk rocks, used to use it a lot. I notice these days though, the data matches the tools more, so I haven’t had to reach for it in a long time.

Reply

My Load Test

Processing DHCP logs with AWK

3 Responses to “Processing DHCP logs with AWK”

Leave a Reply