Monthly Archives: November 2013

awk – Hits by hour for apache and IIS log format

Posted on by

I’ve done this many different ways but this has to be the most efficient way I’ve found to get hits by hour and I get to use the power of awk

The script sets the delimiter of : and counts the number of occurrences of the 2nd field which is the hour field, I add a little word formatting for the date file I’m working with and sort the output

Apache log format

awk -F":" '{count[$2]++}END{for (j in count) {print "11-25-13 hour "j, count[j]" hits"; total+=count[j]} print "Total hits="total}' /log/file |sort

and in an 1/8 of the time it used to take me mixing several commands I now have this output

11-25-13 hour 00 34278 hits
11-25-13 hour 01 28582 hits
11-25-13 hour 02 27139 hits
11-25-13 hour 03 219542 hits
11-25-13 hour 04 33612 hits
11-25-13 hour 05 29900 hits
11-25-13 hour 06 36313 hits
11-25-13 hour 07 48721 hits
11-25-13 hour 08 60941 hits
11-25-13 hour 09 77082 hits
11-25-13 hour 10 99376 hits
11-25-13 hour 11 142141 hits
11-25-13 hour 12 191163 hits
11-25-13 hour 13 218150 hits
11-25-13 hour 14 238086 hits
11-25-13 hour 15 236122 hits
11-25-13 hour 16 268599 hits
11-25-13 hour 17 224519 hits
11-25-13 hour 18 220107 hits
11-25-13 hour 19 223004 hits
11-25-13 hour 20 182992 hits
11-25-13 hour 21 180524 hits
11-25-13 hour 22 182396 hits
11-25-13 hour 23 173174 hits
Total hits=3376463

IIS was slightly different due to the different log format, again I set the delimiter to : this time I count the 1st field add different word formatting and sort based on the 2nd column
IIS Log format

sudo awk -F":" '{count[$1]++}END{for (j in count) {print j" hour", count[j]" hits"; total+=count[j]} print "Total hits="total}' /log/file |sort -k 2

Produces this output

2013-11-25 00 hour 59259 hits
2013-11-25 01 hour 55567 hits
2013-11-25 02 hour 51763 hits
2013-11-25 03 hour 44487 hits
2013-11-25 04 hour 43262 hits
2013-11-25 05 hour 46869 hits
2013-11-25 06 hour 33495 hits
2013-11-25 07 hour 24929 hits
2013-11-25 08 hour 20310 hits
2013-11-25 09 hour 18445 hits
2013-11-25 10 hour 17211 hits
2013-11-25 11 hour 22776 hits
2013-11-25 12 hour 26052 hits
2013-11-25 13 hour 36508 hits
2013-11-25 14 hour 38920 hits
2013-11-25 15 hour 43963 hits
2013-11-25 16 hour 45905 hits
2013-11-25 17 hour 41755 hits
2013-11-25 18 hour 42276 hits
2013-11-25 19 hour 41531 hits
2013-11-25 20 hour 41101 hits
2013-11-25 21 hour 44790 hits
2013-11-25 22 hour 45541 hits
2013-11-24 23 hour 18 hits
2013-11-25 23 hour 49687 hits
Total hits=936444

Good luck and happy reporting

awk – Who is connected, how many connections do they have and what is their connection state

Posted on by

I’ve been busy tuning Varnish to prevent outages and that makes me take a much closer look at things and how to get through things quickly especially when it comes to working with farms of servers. I noticed in my cacti graphs a huge rise in FIN_WAIT_1 connection states on my FreeBSD servers to a degree of 25x the number of established connections so I decided to do some work to see what’s going. What I came to I think will provide some nice insight for many different scenarios.

First how I made my determination of my ratios, I know what connection states I’m looking so I create an array with those values, I know that it’s the 6th field and I’d like a count of where each stands. This is the oneliner

connstates=( FIN_WAIT_1 FIN_WAIT_2 TIME_WAIT ESTABLISHED SYN_RCVD LAST_ACK); for a in ${connstates[@]}; do netstat -n |awk '($6 = /'"${a}"'/){freq['"${a}"']++} END {for (x in freq) {print freq[x], "'"${a}"'", "\n" }}' |sort -nr;done

I added the carriage return to clean up the output

767 FIN_WAIT_1 

103 FIN_WAIT_2

866 TIME_WAIT

54 ESTABLISHED

220 SYN_RCVD

7 LAST_ACK

Now that I have that I want to know who’s connected, how many connections they have by connection state this oneliner takes care of that

connstates=( FIN_WAIT_1 FIN_WAIT_2 TIME_WAIT ESTABLISHED SYN_RCVD LAST_ACK); for a in ${connstates[@]}; do echo -e "\n" $a; netstat -n |awk '($6 = /'"${a}"'/){print $5}'|awk -F \. '{$5 = ""; gsub(/\ /, "."); gsub(/.$/,""); print}' |awk '{freq[$0]++} END {for (x in freq) {print freq[x], x }}' |sort -nr;done

and that produces an output like this

FIN_WAIT_1
627 67.198.71.114
390 64.90.159.102
264 89.241.213.178
221 174.108.76.131
71 186.32.54.114

FIN_WAIT_2
5 66.66.133.117
5 65.0.139.23
5 173.169.40.34
5 166.147.120.16
4 96.246.240.75

TIME_WAIT
98 10.10.10.20
68 10.10.10.22
60 10.10.10.23
60 10.10.10.24
49 10.10.10.25

ESTABLISHED
13 186.32.54.114
9 98.255.88.48
7 64.90.159.102
6 70.208.78.19
5 98.204.42.34

SYN_RCVD
22 108.45.28.123
2 12.160.201.226
1 98.255.88.48

LAST_ACK
6 71.215.198.128
2 66.104.42.194
1 80.58.205.48
1 41.79.120.19
1 121.120.116.205

Some of these gave me a hard time so let’s take a closer look at some of these
I’ve covered the gotchas from using a bash array variable in an earlier blog so I won’t cover that again. What I did discover is awk unkowingly modifies the output. I didn’t understand why I was getting this strange frequency output until I broke down what was happening and that’s when I saw what awk was doing

netstat -n |awk '($6 = /FIN_WAIT_1/)' |head -n 5
tcp4 0 532 10.10.10.169.80 173.175.47.91.55257 1
tcp4 0 532 10.10.10.169.80 173.175.47.91.55256 1
tcp4 0 533 10.10.10.169.80 108.45.28.123.49944 1
tcp4 0 0 10.10.10.169.80 113.197.8.162.41647 1
tcp4 0 0 10.10.10.169.80 113.197.8.162.2879 1

UH? I thought maybe it was how netstat behaved and I just never noticed

 netstat -n |grep FIN_WAIT_1 |head -n 5
tcp4       0  24606 10.10.10.169.80      199.224.118.221.62975  FIN_WAIT_1
tcp4       0   3579 10.10.10.169.80      74.12.184.206.1323     FIN_WAIT_1
tcp4       0    533 10.10.10.169.80      173.175.47.91.57498    FIN_WAIT_1
tcp4       0    533 10.10.10.169.80      173.175.47.91.57497    FIN_WAIT_1
tcp4       0    533 10.10.10.169.80      173.175.47.91.57496    FIN_WAIT_1

Nope

OK so now to account for this we’ve passed the bash variable in and accounted for it in the search, in the print section I’d normally have x as its my variable for the for loop but x was returning a blank field

connstates=( FIN_WAIT_1 FIN_WAIT_2 TIME_WAIT ESTABLISHED SYN_RCVD LAST_ACK); for a in ${connstates[@]};  do netstat -n |awk '($6 = /'"${a}"'/){freq['"${a}"']++} END {for (x in freq) {print freq[x], x, "\n" }}' |sort -nr;done
2513  

167  

789  

128  

213  

6

this is no good so I try passing the bash variable like I did in the search

connstates=( FIN_WAIT_1 FIN_WAIT_2 TIME_WAIT ESTABLISHED SYN_RCVD LAST_ACK); for a in ${connstates[@]};  do netstat -n |awk '($6 = /'"${a}"'/){freq['"${a}"']++} END {for (x in freq) {print freq[x], '"${a}"', "\n" }}' |sort -nr;done
2495  

230  

892  

149  

124  

6

Same thing, then it hit me maybe its not being passed as a string so I added double quotes

connstates=( FIN_WAIT_1 FIN_WAIT_2 TIME_WAIT ESTABLISHED SYN_RCVD LAST_ACK); for a in ${connstates[@]};  do netstat -n |awk '($6 = /'"${a}"'/){freq['"${a}"']++} END {for (x in freq) {print freq[x], "'"${a}"'", "\n" }}' |sort -nr;done
2563 FIN_WAIT_1 

194 FIN_WAIT_2 

901 TIME_WAIT 

108 ESTABLISHED 

158 SYN_RCVD 

5 LAST_ACK

Perfect

The next one I hadn’t had to deal with previously on linux was FreeBSD doesn’t use : for the port associated with the IP address, it uses a .
I used gsub to clean up my formatting

bash variable is looking for one of my states, I know I want the 5th field so I print and pipe the output and want to strip the port so I use gsub, now the 1st gsub adds an additional period at the end of the address so I add a 2nd gsub and I look for any period at the end of the line and remove it and then print the output

netstat -n |awk '($6 = /'"${a}"'/){print $5}'|awk -F \. '{$5 = ""; gsub(/\ /, "."); gsub(/.$/,""); print}'

I hope you’ve found this useful and find ways to expand and modify it for your needs

awk – getting status code by request type

Posted on by

I started off by wanting to see what my request types were and then grew curious what my status codes were for those request types. This is searching my varnishlogs but they are in apache format.

Since I like awk… I started by searching the 6th field for GET request types
awk ‘($6 ~ /GET/)’ varnishlog |wc -l 
While this is nice its very manual and doesn’t give me a whole lot of useful info except every request that’s a get

So let’s take it a step farther, using the frequency function from awk
awk ‘{freq[$6]++} END {for (x in freq) {print x, freq[x]}} varnishlog
This produces a nicer output and tells me how many of each request type that I got but doesn’t tell the status of those request types

let’s take it another step further, we’re going to search the 9th field for 200 statuses and report against the request type and lets add numeric sorting on the 2nd output field
awk ‘($9 ~ /200/){freq[$6]++} END {for (x in freq) {print x, freq[x]}}’ varnishlog |sort -nr -k 2

Well now we can see all of our requests are not 200s, let’s get a clear view of what’s happening then.  I’ll create an array of the status codes I care about and move to a for loop, due to my use of the array I have to take special care using it in the search field, I also add a carriage return to the output of awk to make the output easier to read
statuscodes=( 200 301 302 400 403 404 410 500 501 503 );for a in ${statuscodes[@]};do echo $a statuses;awk ‘($9 ~ /'”${a}”‘/){freq[$6]++} END {for (x in freq) {print x, freq[x], “\n”}}’ varnishlog |sort -nr -k 2;done