Analyzing Log Files with Python and Prefix Trees

2012-‐07-‐16 09:12 ****************** 2012-‐07-‐16 09:13 ********************
493 2012-‐07-‐16 09:14 **************************************** 982 2012-‐07-‐16 09:15 ************************************** 939 2012-‐07-‐16 09:16 **************************** 697 2012-‐07-‐16 09:17 ************************************* 905 2012-‐07-‐16 09:18 *********************************** 848 2012-‐07-‐16 09:19 *********************** 565 2012-‐07-‐16 09:20 ************************* 625 2012-‐07-‐16 09:21 ************** 355 2012-‐07-‐16 09:22 **************************** 699 2012-‐07-‐16 09:23 ******************************** 787 2012-‐07-‐16 09:24 ************************* 619 2012-‐07-‐16 09:25 ************************************* 912 2012-‐07-‐16 09:26 ********************************** 828 2012-‐07-‐16 09:27 ************************************* 904 2012-‐07-‐16 09:28 ***************************** 715 2012-‐07-‐16 09:29 ************************************** 919 2012-‐07-‐16 09:30 *********************** 558 2012-‐07-‐16 09:31 *********************************** 864 2012-‐07-‐16 09:32 ***************************** 704 2012-‐07-‐16 09:33 *************************** 658 2012-‐07-‐16 09:34 *************************** 666 2012-‐07-‐16 09:35 ************************* 618 2012-‐07-‐16 09:36 ************************ 594 2012-‐07-‐16 09:37 ******************************** 793 2012-‐07-‐16 09:38 ************************************* 902 2012-‐07-‐16 09:39 ***************************************************** 1278 6 09:40 ****************************** 740 836 Analyzing Log Files with Python & Prefix Trees

The Problem My web app is throwing lots of errors.
How can I correlate the errors with changes in the environment?

71.58.17.84 -‐ -‐ [16/Jul/2012:01:26:06 -‐0700] "GET / HTTP/1.1" 500 6645
"referrer" "useragent"

71.58.17.84 -‐ -‐ [16/Jul/2012:01:26:06 -‐0700] "GET / HTTP/1.1" 500 6645
"referrer" "useragent" that's an error!

awk '$9 == "500" { print $4,$5 }' 71.58.17.84 -‐
-‐ [16/Jul/2012:01:26:06 -‐0700] "GET / HTTP/1.1" 200 6645 "referrer" "useragent" AWK

awk '$9 == "500" { print $4,$5 }' 71.58.17.84 -‐
-‐ [16/Jul/2012:01:26:06 -‐0700] "GET / HTTP/1.1" 500 6645 "referrer" "useragent" AWK

How many errors? awk '$9 == "500" { print }'
| wc -‐l

When did they start? awk '$9 == "500" { print
}' | head

Generally... What is the frequency of errors?

Let's make a histogram!

awk '$9 == "500" { print $4 }' | cut
-‐c 14,15 | Extract the hours... [16/Jul/2012:01:33:51

awk '$9 == "500" { print $4 }' | cut
-‐c 14,15 | sort | sort them... Yes, logs are already chronological (sorted), but maybe we're combining multiple log ﬁles...

awk '$9 == "500" { print $4 }' | cut
-‐c 14,15 | sort | uniq -‐c and count the uniques...

$ awk '$9 == "500" { print $4 }' log
| cut -‐c 14,15 | sort | uniq -‐c 33 01 75 02 127 03 157 04 406 05 430 06 640 07 828 08 934 09 875 10 741 11 615 12

$ awk '$9 == "500" { print $4 }' log
| cut -‐c 14,15 | sort | uniq -‐c 33 01 75 02 127 03 157 04 406 05 430 06 640 07 828 08 934 09 875 10 741 11 615 12 count

$ awk '$9 == "500" { print $4 }' log
| cut -‐c 14,15 | sort | uniq -‐c 33 01 75 02 127 03 157 04 406 05 430 06 640 07 828 08 934 09 875 10 741 11 615 12 hour

$ awk '$9 == "500" { print $4 }' log
| cut -‐c 14,15 | sort | uniq -‐c 33 01 75 02 127 03 157 04 406 05 430 06 640 07 828 08 934 09 875 10 741 11 615 12 Most errors happened between 9 & 10 AM

awk + cut + sort + uniq

awk + cut + sort + uniq Need to know
date ﬁeld Need to know hour position In-memory sort

can we do better? http://ra3ndy.deviantart.com/art/Sad-Panda-69204875

$ pystogram /var/log/apache2/access.log 2012-‐07-‐16 01 **
1493 2012-‐07-‐16 02 *** 2819 2012-‐07-‐16 03 ******* 5753 2012-‐07-‐16 04 ********** 7721 2012-‐07-‐16 05 ******************* 14833 2012-‐07-‐16 06 ************************** 19914 2012-‐07-‐16 07 ********************************** 25626 2012-‐07-‐16 08 ***************************************************** 39901 2012-‐07-‐16 09 ******************************************************* 40943 2012-‐07-‐16 10 ************************************************* 36690 2012-‐07-‐16 11 ******************************************** 32967 2012-‐07-‐16 12 ************************************** 28989

$ awk '$9 == "500" { print }' log |
pystogram 2012-‐07-‐16 01 ** 33 2012-‐07-‐16 02 **** 75 2012-‐07-‐16 03 ******* 127 2012-‐07-‐16 04 ********* 157 2012-‐07-‐16 05 ************************ 406 2012-‐07-‐16 06 ************************** 430 2012-‐07-‐16 07 *************************************** 640 2012-‐07-‐16 08 ************************************************** 828 2012-‐07-‐16 09 ********************************************************* 934 2012-‐07-‐16 10 ***************************************************** 875 2012-‐07-‐16 11 ********************************************* 741 2012-‐07-‐16 12 ************************************* 615

$ awk '$9 == "500" { print }' log |
pystogram 2012-‐07-‐16 01 ** 33 2012-‐07-‐16 02 **** 75 2012-‐07-‐16 03 ******* 127 2012-‐07-‐16 04 ********* 157 2012-‐07-‐16 05 ************************ 406 2012-‐07-‐16 06 ************************** 430 2012-‐07-‐16 07 *************************************** 640 2012-‐07-‐16 08 ************************************************** 828 2012-‐07-‐16 09 ********************************************************* 934 2012-‐07-‐16 10 ***************************************************** 875 2012-‐07-‐16 11 ********************************************* 741 2012-‐07-‐16 12 ************************************* 615 $ pystogram /var/log/apache2/access.log 2012-‐07-‐16 01 ** 1493 2012-‐07-‐16 02 *** 2819 2012-‐07-‐16 03 ******* 5753 2012-‐07-‐16 04 ********** 7721 2012-‐07-‐16 05 ******************* 14833 2012-‐07-‐16 06 ************************** 19914 2012-‐07-‐16 07 ********************************** 25626 2012-‐07-‐16 08 ***************************************************** 39901 2012-‐07-‐16 09 ******************************************************* 40943 2012-‐07-‐16 10 ************************************************* 36690 2012-‐07-‐16 11 ******************************************** 32967 2012-‐07-‐16 12 ************************************** 28989 same shape

$ awk '$9 == "500" { print }' log |
pystogram 2012-‐07-‐16 01 ** 33 2012-‐07-‐16 02 **** 75 2012-‐07-‐16 03 ******* 127 2012-‐07-‐16 04 ********* 157 2012-‐07-‐16 05 ************************ 406 2012-‐07-‐16 06 ************************** 430 2012-‐07-‐16 07 *************************************** 640 2012-‐07-‐16 08 ************************************************** 828 2012-‐07-‐16 09 ********************************************************* 934 2012-‐07-‐16 10 ***************************************************** 875 2012-‐07-‐16 11 ********************************************* 741 2012-‐07-‐16 12 ************************************* 615 $ pystogram /var/log/apache2/access.log 2012-‐07-‐16 01 ** 1493 2012-‐07-‐16 02 *** 2819 2012-‐07-‐16 03 ******* 5753 2012-‐07-‐16 04 ********** 7721 2012-‐07-‐16 05 ******************* 14833 2012-‐07-‐16 06 ************************** 19914 2012-‐07-‐16 07 ********************************** 25626 2012-‐07-‐16 08 ***************************************************** 39901 2012-‐07-‐16 09 ******************************************************* 40943 2012-‐07-‐16 10 ************************************************* 36690 2012-‐07-‐16 11 ******************************************** 32967 2012-‐07-‐16 12 ************************************** 28989 same FREQUENCY

$ pystogram /var/log/apache2/access* 2012-‐07-‐16 *****************************
203842 2012-‐07-‐17 ******************** 164364 2012-‐07-‐18 ********************************************************* 402943 2012-‐07-‐19 ******************************************************* 396935 2012-‐07-‐20 ***************************************************** 374234 2012-‐07-‐21 ******************************************************* 408101 2012-‐07-‐22 ******************************************************** 413942 2012-‐07-‐23 **************************** 198854 2012-‐07-‐24 ****************** 142964 Analyze multiple log ﬁles... ...pystogram chooses the best bucket size

$ grep 16/Jul/2012:09 /var/log/apache2/access.log | pystogram 2012-‐07-‐16 09:00 *********************************
819 2012-‐07-‐16 09:01 ********************** 539 2012-‐07-‐16 09:02 ************************ 594 2012-‐07-‐16 09:03 ************************ 579 2012-‐07-‐16 09:04 ************************** 648 2012-‐07-‐16 09:05 ***************************** 719 2012-‐07-‐16 09:06 ********************************** 826 2012-‐07-‐16 09:07 ************************** 627 2012-‐07-‐16 09:08 ************************* 609 ... Analyze ﬁltered data... ...pystogram chooses the best bucket size

How does it work?

def main(): histogram = Histogram()
for line in fileinput.input(): timestamp = get_timestamp(line) if timestamp is not None: histogram.count(timestamp) chart = AsciiChart(histogram) chart.draw()

def main(): histogram = Histogram()
for line in fileinput.input(): timestamp = get_timestamp(line) if timestamp is not None: histogram.count(timestamp) chart = AsciiChart(histogram) chart.draw() histogram.count(timestamp)

class Histogram(object): def __init__(self):
""" Construct a Histogram instance. """ self.tree = PrefixTree() def count(self, timestamp): """ Increment the count for this timestamp. """ self.tree.incr(timestamp)

class Histogram(object): def __init__(self):
""" Construct a Histogram instance. """ self.tree = PrefixTree() def count(self, timestamp): """ Increment the count for this timestamp. """ self.tree.incr(timestamp) self.tree = PrefixTree()

Prefix Tree? So what's a

>>> tree.incr('pony')

tree >>> tree.incr('pony')

tree P >>> tree.incr('pony')

tree P O >>> tree.incr('pony')

tree P O N >>> tree.incr('pony')

tree P O N Y >>> tree.incr('pony')

tree P O N Y 1 >>> tree.incr('pony')

tree P O N Y 1 >>> tree.incr('pony') >>> tree.sum()
1

tree P O N Y 2 >>> tree.incr('pony') >>> tree.sum()
1 >>> tree.incr('pony') >>> tree.sum() 2

tree P O N Y C A T 2 1
>>> tree.incr('cat') >>> tree.sum() 3

tree P O N Y C A T O W
2 1 1 >>> tree.incr('cow') >>> tree.sum() 4

tree P O N Y A T O W 2
1 1 >>> node = tree.find('c') >>> node.sum() 2 C

tree P O N Y A T O W 2
1 1 >>> node = tree.find('cat') >>> node.sum() 1 C

Prefix Trees work great for dates

tree 2013 7 8 20 24 8 1 1 1
>>> tree.incr((2013, 7, 20)) >>> tree.incr((2013, 7, 24)) >>> tree.incr((2013, 8, 8))

2013 7 8 20 24 8 1 1 1 >>>
tree.count() 3 >>> tree.find((2013, 7)).count() 2 tree

class PrefixTree(collections.defaultdict): def __init__(self):
super(PrefixTree, self).__init__(PrefixTree) self.value = 0 Implemented as a "recursive" defaultdict

github.com/claymation/pystogram

n @claymcclure / daemons.net

Analyzing Log Files with Python and Prefix Trees

Analyzing Log Files with Python and Prefix Trees

More Decks by Clay McClure

Other Decks in Programming

Featured

Transcript