Wednesday 2 November 2011

Linux Time (costing me time!)

Recently I had to *quickly* analyse some squid logs on a compromised box, fortunately for me the attacker didn't do any post exploitation log clearance so there was plenty for me to look at. :-)
Anyway, this particular squid setup was printing logs with the linux time stamp, for those of you who don't know about linux/unix time stamps, they show the number of seconds since 00:00, January 1, 1970 GMT, referred to as the Epoch.
I'm not one for using GUI's to do such a simple task so I used a bit of awk, it's very simple.
Here's an extract from some other squid logs, that shows the system time in column 1:
 [root@gateway ~]# tail -f /var/log/squid/access.log
1320259150.490      1 10.50.60.193 TCP_MEM_HIT/200 811 GET http://safebrowsing-cache.google.com/safebrowsing/rd/ChFnb29nLXBoaXNoLXNoYXZhchAAGPvRCiCE0goqBf-oAgA_MgX7qAIADw - NONE/- application/vnd.google.safebrowsing-chunk
1320259167.644    407 10.44.254.109 TCP_MISS/200 4854 GET http://twitter.com/account/available_features - DIRECT/199.59.149.230 text/javascript
1320259173.477     84 10.44.254.213 TCP_MISS/200 543 GET http://go.sky.com/vod/viewless/currentTime.do - DIRECT/2.17.237.52 text/plain
1320259231.937    472 10.44.254.170 TCP_MISS/200 759 GET http://search.twitter.com/search.json? - DIRECT/199.59.148.201 application/json
1320259232.013    356 10.44.254.170 TCP_MISS/200 744 GET http://search.twitter.com/search.json? - DIRECT/199.59.148.201 application/json
1320259289.600    388 10.44.254.109 TCP_MISS/200 1936 GET http://api.twitter.com/1/trends/23424975.json? - DIRECT/199.59.148.20 application/json
1320259322.271    396 10.44.254.170 TCP_MISS/200 2021 GET http://www.google.com/reader/api/0/unread-count? - DIRECT/74.125.230.145 text/javascript
1320259347.605    393 10.44.254.109 TCP_MISS/200 4854 GET http://twitter.com/account/available_features - DIRECT/199.59.148.82 text/javascript
1320259369.710    191 10.44.254.170 TCP_MISS/200 728 GET http://query.yahooapis.com/v1/public/yql? - DIRECT/87.248.113.166 application/json
1320259370.535   1016 10.44.254.170 TCP_MISS/200 1349 GET http://weather.yahooapis.com/forecastjson? - DIRECT/87.248.122.181 application/json
Now with a bit of awk we can add a human readable time-stamp next to the epoch time-stamp:
 [root@gateway ~]# tail -f /var/log/squid/access.log | awk '{ print strftime("%y-%m-%d %H:%M:%S"), $0; }'
11-11-02 18:45:36 1320259435.980    916 10.44.254.186 TCP_MISS/200 32393 GET http://twitter.com/statuses/user_timeline/d3m0n35.json - DIRECT/199.59.149.198 application/json
11-11-02 18:45:36 1320259453.347    116 10.44.254.213 TCP_MISS/200 710 POST http://safebrowsing.clients.google.com/safebrowsing/downloads? - DIRECT/209.85.143.101 application/vnd.google.safebrowsing-update
11-11-02 18:45:36 1320259453.438     53 10.44.254.213 TCP_MEM_HIT/200 527 GET http://safebrowsing-cache.google.com/safebrowsing/rd/ChFnb29nLXBoaXNoLXNoYXZhchABGP6QBSD-kAUyBX5IAQAB - NONE/- application/vnd.google.safebrowsing-chunk
11-11-02 18:45:36 1320259453.503     55 10.44.254.213 TCP_MISS/200 951 GET http://safebrowsing-cache.google.com/safebrowsing/rd/ChFnb29nLXBoaXNoLXNoYXZhchAAGPvRCiCE0goqBQGpAgAPMgX7qAIAPw - DIRECT/209.85.147.139 application/vnd.google.safebrowsing-chunk
11-11-02 18:45:36 1320259521.453     80 10.44.254.213 TCP_REFRESH_HIT/304 550 GET http://images.apple.com/main/rss/hotnews/hotnews.rss - DIRECT/77.109.169.163 application/xml
11-11-02 18:45:36 1320259521.489    116 10.44.254.213 TCP_MISS/200 51415 GET http://news.google.com/? - DIRECT/74.125.230.128 application/xml
11-11-02 18:45:36 1320259522.144    891 10.44.254.213 TCP_MISS/304 549 GET http://techie-buzz.com/how-to/uninstall-programs-on-mac.html/feed - DIRECT/72.14.188.242 -
11-11-02 18:45:36 1320259527.646    421 10.44.254.109 TCP_MISS/200 4854 GET http://twitter.com/account/available_features - DIRECT/199.59.148.10 text/javascript
11-11-02 18:45:36 1320259532.430    404 10.44.254.170 TCP_MISS/200 743 GET http://search.twitter.com/search.json? - DIRECT/199.59.148.201 application/json
11-11-02 18:45:36 1320259532.531    555 10.44.254.170 TCP_MISS/200 2095 GET http://search.twitter.com/search.json? - DIRECT/199.59.148.201 application/json
So what's this awk syntax doing?
  awk '{ print strftime("%y-%m-%d %H:%M:%S"), $0; }' 
The logs are piped to awk, awk then processes the input with the 'strftime' flag which formats the timestamp according to your requirements, in this case:
 %y for year-%m for month-%d for day then %H for hour:%M for minute:%S for second 
The last piece of the syntax is the $0 variable that tells awk to print every subsequent line.