Slide 1

Slide 1 text

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

Slide 2

Slide 2 text

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

Slide 3

Slide 3 text

RTFL

Slide 4

Slide 4 text

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

Slide 5

Slide 5 text

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

Slide 6

Slide 6 text

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

Slide 7

Slide 7 text

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

Slide 8

Slide 8 text

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

Slide 9

Slide 9 text

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

Slide 10

Slide 10 text

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

Slide 11

Slide 11 text

Generally... What is the frequency of errors?

Slide 12

Slide 12 text

Let's make a histogram!

Slide 13

Slide 13 text

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

Slide 14

Slide 14 text

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 files...

Slide 15

Slide 15 text

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

Slide 16

Slide 16 text

$  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

Slide 17

Slide 17 text

$  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

Slide 18

Slide 18 text

$  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

Slide 19

Slide 19 text

$  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

Slide 20

Slide 20 text

awk + cut + sort + uniq

Slide 21

Slide 21 text

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

Slide 22

Slide 22 text

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

Slide 23

Slide 23 text

$  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

Slide 24

Slide 24 text

No content

Slide 25

Slide 25 text

$  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

Slide 26

Slide 26 text

$  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

Slide 27

Slide 27 text

$  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

Slide 28

Slide 28 text

$  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 files... ...pystogram chooses the best bucket size

Slide 29

Slide 29 text

$  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 filtered data... ...pystogram chooses the best bucket size

Slide 30

Slide 30 text

How does it work?

Slide 31

Slide 31 text

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()

Slide 32

Slide 32 text

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)

Slide 33

Slide 33 text

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)

Slide 34

Slide 34 text

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()

Slide 35

Slide 35 text

Prefix Tree? So what's a

Slide 36

Slide 36 text

>>>  tree.incr('pony')

Slide 37

Slide 37 text

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

Slide 38

Slide 38 text

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

Slide 39

Slide 39 text

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

Slide 40

Slide 40 text

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

Slide 41

Slide 41 text

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

Slide 42

Slide 42 text

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

Slide 43

Slide 43 text

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

Slide 44

Slide 44 text

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

Slide 45

Slide 45 text

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

Slide 46

Slide 46 text

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

Slide 47

Slide 47 text

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

Slide 48

Slide 48 text

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

Slide 49

Slide 49 text

Prefix Trees work great for dates

Slide 50

Slide 50 text

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))

Slide 51

Slide 51 text

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

Slide 52

Slide 52 text

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

Slide 53

Slide 53 text

github.com/claymation/pystogram

Slide 54

Slide 54 text

n @claymcclure / daemons.net