Front page
Archive
Silflay Hraka?


Bigwig is a systems administrator at a public university
Hrairoo is the proprietor of a quality used bookstore
Kehaar is.
Woundwort is a professor of counseling at a private university

The Hraka RSS feed

Email
bigwig AT nc.rr.com

Friends of Hraka
InstaPundit
Daily Pundit
cut on the bias
Meryl Yourish
This Blog Is Full Of Crap
Winds of Change
A Small Victory
Silent Running
Dr. Weevil
Little Green Footballs
ColdFury
Oceanguy
Fragments from Floyd
VodkaPundit
Allah
The Feces Flinging Monkey
the skwib
Dean's World
Little Tiny Lies
The Redsugar Muse
Sperari
Natalie Solent
From the Mrs.
ErosBlog
The Anti-Idiotarian Rottweiler
On the Third Hand
Public Nuisance
Not a Fish
Rantburg
AMCGLTD
WeckUpToThees!
Electric Venom
Skippy, The Bush Kangaroo
Common Sense and Wonder
Neither Here Nor There
Wizbang!
Bogieblog
ObscuroRant
RocketJones
The Greatest Jeneration
Ravenwolf
Ipse Dixit
TarHeelPundit
Blog On the Run
blogatron
Redwood Dragon
Notables
Greeblie Blog
Have A Cuppa Tea
A Dog's Life
IMAO
Zonitics.com
Iberian Notes
Midwest Conservative Journal
A Voyage to Arcturus
HokiePundit
Trojan Horseshoes
In Context
dcthornton.blog
The People's Republic of Seabrook
Country Store
Blog Critics
Chicago Boyz
Hippy Hill News
Kyle Still Free Press
The Devil's Excrement
The Fat Guy
War Liberal
Assume the Position
Balloon Juice
Iron Pen In A Velvet Glove
IsraPundit
Freedom Lives
Where Worlds Collide
Knot by Numbers
How Appealing
South Knox Bubba
Heretical Ideas
The Kitchen Cabinet
Dustbury.com
tonecluster
Bo Cowgill
mtpolitics.net
Raving Atheist
The Short Strange Trip
Shark Blog
Hoplites
Jimspot
Ron Bailey's Weblog
Cornfield Commentary
Testify!
Northwest Notes
pseudorandom
The Blog from the Core
Ain'tNoBadDude
CroMagnon
The Talking Dog
WTF Is It Now??
Blue Streak
Smarter Harper's Index
nikita demosthenes
Bloviating Inanities
Sneakeasy's Joint
Ravenwood's Universe
The Eleven Day Empire
World Wide Rant
All American
Pdawwg
The Rant
The Johnny Bacardi Show
The Head Heeb
Viking Pundit
Mercurial
Oscar Jr. Was Here
Just Some Poor Schmuck
Katy & Bruce Loebrich
But How's The Coffee?
Roscoe Ellis
Foolsblog
Sasha Castel
Dodgeblogium
Susskins Central Dispatch
DoggerelPundit
Josh Heit
Attaboy
Aaron's Rantblog
MojoMark
As I was saying...
Blog O' Dob
Dr. Frank's Blogs Of War
Betsy's Page
A Knob for Brightness
Fresh Bilge
The Politburo Diktat
Drumwaster's rants
Curt's Page
The Razor
An Unsealed Room
The Legal Bean
Helloooo chapter two!
As I Was Saying...
SkeptiLog AGOG!
Tong family blog
Vox Beth
Velociblog
I was thinking
Judicious Asininity
This Woman's Work
Fragrant Lotus
DaGoddess
Single Southern Guy
Caerdroia
GrahamLester.Com
Jay Solo's Verbosity
TacJammer
Snooze Button Dreams
Horologium
You Big Mouth, You!
From the Inside looking Out
Night of the Lepus
No Watermelons Allowed
From The Inside Looking Out
Lies, Damn Lies, and Statistics
Suburban Blight
Aimless
The SmarterCop
Dog of Flanders
From Behind the Wall of Sleep
Beaker's Corner
Bad State of Gruntledness
Who Tends The Fires
Granny Rant
Elegance Against Ignorance
Moxie.nu
Eccentricity
Say What?
Blown Fuse
Wait 'til Next Year
The Pryhills
The Whomping Willow
The National Debate
The Skeptician
Zach Everson
MonkeyWatch
Geekward Ho
Argghhh!!!
Life in New Orleans
Rotten Miracles
Fringe
The Biomes Blog
illinigirl
See What You Share
Truthprobe
Blog d’Elisson
Your Philosophy Sucks
Watauga Rambler
Socialized Medicine
Consternations
Verging on Pertinence
Read My Lips
ambivablog
Soccerdad
The Flannel Avenger
Butch Howard's WebLog
Castle Argghhh!
Andrew Hofer
kschlenker.com
Moron Abroad
White Pebble
Darn Floor
Wizblog
tweedler
Pajama Pundits
BabyTrollBlog
Cadmusings
Goddess Training 101
A & W
Medical Madhouse
Slowly Going Sane
The Oubliette
American Future
Right Side Redux
See The Donkey
Newbie Trucker
The Right Scale
Running Scared
Ramblings Journal
Focus On Reality
Wyatt's Torch

January 06, 2005

Cutting And Splicing

Spent the morning trying to meld information from three separate Apache web server logs into one file. Well, not the whole morning. Depending on the size of the logs, any competent UNIX user could take three and make them into one in a matter of seconds. I am at least that, by now. My problem was that we were only interested in specific information from those logs, and to be useful, the information within that one had to be sorted by IP address, then by time, then by the server.

The whole situation arose because of something called an "assessment" in UNC's Blackboard online courseware. I assume it's a form of some sort where professors rank their students, or vice-versa, but given Blackboard's penchant for making simple things unnecessarily complicated, it could be the free verse engine for the English Department.

Anyway, these assessments periodically fail, for no reason that we have been able to detect, though recently the Blackboard testing staff has developed the hypothesis that assessments might fail if for some reason a user was switched from one of the machines in our three-server pool to another one while in the act of creating/submitting an assessment.

The problem with this hypothesis is that, if true, then something is causing our load balancer to act in a manner that it should not. Incoming connections for blackboard are assigned to one of the three servers by the load balancer based on which one is the least busy at the moment, and once a connection is sent to one server, there it should stay there until the user logs out, or the connection is broken on our end, say if Blackboard has one of its periodic breakdowns, or by an enraged sysadmin beating the server to death with a aluminum bat.

The melding of the three logs into one is the first step in testing this hypothesis. I've got to take each log, pull out the information I'm interested in from each of the 100,000 plus log entries therein (IP address, server name and timestamp of the entry) then arrange the information from all three in the target file so that the entries are sorted; first by IP address, then by timestamp, then by machine name.

Here's a typical entry from the access log on one of the servers--let's call it "access.log". The bits I want are in bold.

24.163.116.72 bloodyhell.unc.edu - [05/Jan/2005:23:55:29 -0500] "GET /bin/common/content.pl?action=LIST&course_id=_148526_1&render_type=DEFAULT&content_id=_1289354_1 HTTP/1.1" 200 2669 "https://blackboard.unc.edu/bin/common/toc.pl?course_id=_148526_1&mini=Y" "Mozilla/5.0 (Windows; U; Windows NT 5.1; rv:1.7.3) Gecko/20040913 Firefox/0.10.1"

The nice thing here is that the all information I want is at the beginning of the line. The bad news is that it's not in the correct order. The IP address is ok, but the server name (bloodyhell.unc.edu) precedes the timestamp. No worries, I'll deal with that later.

First step, get the info I want, and move it to the destination file. Simple, really.

# cat access.log | cut -d" " -f1,2,4 > temp1

In English, the above means "Print out the access.log file in its entirety (cat access.log), then(|) cut (cut) out the first, second and fourth fields (-f1,2,4) from each line--which, by the way, are separated by spaces(-d" ") and put that output ( > ) in a new file (temp1).

If I then look at my new file, this is what I see

24.163.116.72 bloodyhell.isis.unc.edu [05/Jan/2005:23:55:29

Nice, but the server name is in the wrong spot. Were I to sort the contents of the file now, the timestamps would be the last thing sorted, and I would bee unable to see exactly what happened to a user's session in the order that it happened.

So somehow I need to switch the timestamp and server names around. My first thought is to try to change the cut order around;

"cut -d" " -f1,4,2"

but that has no effect on the lines in the new file. The order is still IP, Name, Timestamp.

My second thought is to see if the "sort" command I plan on running on the file later is able to sort on multiple fields, but that particular functionality is not part of the command.

Were I to mix environments, I could make the final file a .txt file, import it into Microsoft Access on my Windows PC, rearrange the fields so that they were in the right order, then write the data back out to a text file, but that really would take all morning. I decide instead to solve the problem by manually editing the target file after pulling the data I need out of each log.

This time, this is the command I run.

# cat access.log | cut -d" " -f1,4,5 > temp1

which gives me

24.163.116.72 [05/Jan/2005:23:55:29 -0500]

The server name is gone, and there's a "-0500]" there that wasn't before. It's part of the timestamp that didn't make it before, as there's a space between it and the rest of the timestamp. It's the number of hours offset from Greenwich standard time, negative five in our case. The nice thing about it is, regardless of the actual time, that part of the entry will never change. What I'm going to do is replace it, 100,000 plus times, with the machine name.

To do this I need to open up the "temp1" file in the vi editor, which I use all the time. Others swear by emacs, or pico, but all I know is vi. Once the file is open, all I need do to replace the "-0500]" is type

:1,$s/-0500\]/bloodyhell/

which will make all 100,000 changes in a couple of seconds. Essentially I'm telling the editor program to replace every instance of "-0500]" with "bloodyhell." The backslash between the final zero and the bracket is there to tell the program that the bracket actually is a bracket, and not a special character. Without the backslash, the program would see the bracket, think "I've reached the end of a set," and become confused, as it never saw the bracket that means "the beginning of a set." The forward slashes are there as delimiters that allow the editing program to differentiate between "that which needs to be replaced" and "that with which I am replacing it." The colon is there to let the program know that special commands are coming, the 1,$ means "start and the beginning and go to the end of the file" and "s" means replace.

So now my line, and all the 99,999 beneath it, looks very much like this;

24.163.116.72 [05/Jan/2005:23:55:29 bloodyhell

All I need do is repeat the process for the logs from the other two servers; sonofabitch.unc.edu and damnpissant.unc.edu, though the command changes slightly since I am appending the data from those two logs to the end of the "temp1" file;

# cat access.log | cut -d" " -f1,4,5 >> temp1

It’s the second "greater than" sign that makes the difference between "write to," which will overwrite anything in the target file, and "append to," which sticks everything in at the end of the file.

Finally, and by "finally" I mean "15 or so minutes after I started," I have all the data I need, though it still isn't sorted. Once again, easy-peasy;

# cat temp1 | sort -o temp2

In English: "Print out the access.log file in its entirety, sort all the lines--1 comes before 2, l comes before r, numbers come before letters--then write that nicely sorted data that to another file, temp2, in this case."

In Engrish: "Plint out the access.rog fire in its entilety, solt arr the rines--1 comes befole 2, r comes befole l, numbels come befole rettels--then wlite that nicery solted data that to anothel fire, temp2, in this case."

Now, I'm finally able to scan the temp2 file, looking for the theoretical multi-machine session that destroys assessments.

Lo and behold;

152.2.61.63 [05/Jan/2005:10:06:32 bloodyhell
152.2.61.63 [05/Jan/2005:10:06:32 bloodyhell
152.2.61.63 [05/Jan/2005:10:06:33 bloodyhell
152.2.61.63 [05/Jan/2005:10:06:33 bloodyhell
152.2.61.63 [05/Jan/2005:10:06:35 bloodyhell
152.2.61.63 [05/Jan/2005:10:06:37 bloodyhell
152.2.61.63 [05/Jan/2005:12:38:57 sonofabitch
152.2.61.63 [05/Jan/2005:12:38:58 damnpissant
152.2.61.63 [05/Jan/2005:12:38:59 damnpissant
152.2.61.63 [05/Jan/2005:12:39:42 sonofabitch
152.2.61.63 [05/Jan/2005:12:39:43 sonofabitch
152.2.61.63 [05/Jan/2005:12:39:43 damnpissant
152.2.61.63 [05/Jan/2005:12:39:43 damnpissant
152.2.61.63 [05/Jan/2005:12:39:44 damnpissant
152.2.61.63 [05/Jan/2005:12:39:46 sonofabitch
152.2.61.63 [05/Jan/2005:12:39:47 sonofabitch
152.2.61.63 [05/Jan/2005:12:39:47 damnpissant
152.2.61.63 [05/Jan/2005:12:40:01 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:01 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 bloodyhell
152.2.61.63 [05/Jan/2005:12:40:02 damnpissant
152.2.61.63 [05/Jan/2005:12:40:02 damnpissant
152.2.61.63 [05/Jan/2005:12:40:02 damnpissant
152.2.61.63 [05/Jan/2005:12:40:02 damnpissant
152.2.61.63 [05/Jan/2005:12:40:02 damnpissant
152.2.61.63 [05/Jan/2005:12:40:02 damnpissant
152.2.61.63 [05/Jan/2005:12:40:02 damnpissant
152.2.61.63 [05/Jan/2005:12:40:02 damnpissant
152.2.61.63 [05/Jan/2005:12:40:02 damnpissant
152.2.61.63 [05/Jan/2005:12:40:02 damnpissant
152.2.61.63 [05/Jan/2005:12:48:25 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:25 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:25 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:25 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:25 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:25 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:25 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:26 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:26 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:26 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:26 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:26 damnpissant
152.2.61.63 [05/Jan/2005:12:48:26 damnpissant
152.2.61.63 [05/Jan/2005:12:48:26 damnpissant
152.2.61.63 [05/Jan/2005:12:48:26 damnpissant
152.2.61.63 [05/Jan/2005:12:48:26 damnpissant
152.2.61.63 [05/Jan/2005:12:48:27 damnpissant
152.2.61.63 [05/Jan/2005:12:48:27 damnpissant
152.2.61.63 [05/Jan/2005:12:48:28 sonofabitch
152.2.61.63 [05/Jan/2005:12:48:29 damnpissant
152.2.61.63 [05/Jan/2005:12:48:38 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:38 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:38 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:38 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:38 damnpissant
152.2.61.63 [05/Jan/2005:12:48:38 damnpissant
152.2.61.63 [05/Jan/2005:12:48:38 damnpissant
152.2.61.63 [05/Jan/2005:12:48:38 damnpissant
152.2.61.63 [05/Jan/2005:12:48:38 damnpissant
152.2.61.63 [05/Jan/2005:12:48:40 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:40 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:40 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:41 damnpissant
152.2.61.63 [05/Jan/2005:12:48:41 damnpissant
152.2.61.63 [05/Jan/2005:12:48:43 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:43 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:43 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:43 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:43 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:43 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:43 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:43 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:43 bloodyhell
152.2.61.63 [05/Jan/2005:12:48:43 damnpissant
152.2.61.63 [05/Jan/2005:12:48:43 damnpissant
152.2.61.63 [05/Jan/2005:12:48:43 damnpissant
152.2.61.63 [05/Jan/2005:12:48:43 damnpissant
152.2.61.63 [05/Jan/2005:12:48:43 damnpissant
152.2.61.63 [05/Jan/2005:12:49:02 damnpissant
152.2.61.63 [05/Jan/2005:12:49:02 damnpissant
152.2.61.63 [05/Jan/2005:12:49:02 damnpissant
152.2.61.63 [05/Jan/2005:12:49:02 damnpissant
152.2.61.63 [05/Jan/2005:12:49:02 damnpissant
152.2.61.63 [05/Jan/2005:12:49:04 bloodyhell
152.2.61.63 [05/Jan/2005:12:49:18 sonofabitch
152.2.61.63 [05/Jan/2005:12:49:19 damnpissant
152.2.61.63 [05/Jan/2005:15:23:21 damnpissant
152.2.61.63 [05/Jan/2005:15:23:21 damnpissant
152.2.61.63 [05/Jan/2005:15:23:21 damnpissant
152.2.61.63 [05/Jan/2005:15:23:21 damnpissant
152.2.61.63 [05/Jan/2005:15:23:21 damnpissant
152.2.61.63 [05/Jan/2005:15:23:22 sonofabitch
152.2.61.63 [05/Jan/2005:15:23:22 sonofabitch
152.2.61.63 [05/Jan/2005:15:23:22 sonofabitch
152.2.61.63 [05/Jan/2005:15:23:22 sonofabitch
152.2.61.63 [05/Jan/2005:15:23:22 sonofabitch
152.2.61.63 [05/Jan/2005:15:23:22 sonofabitch
152.2.61.63 [05/Jan/2005:15:23:22 sonofabitch
152.2.61.63 [05/Jan/2005:15:23:22 damnpissant
152.2.61.63 [05/Jan/2005:15:23:22 damnpissant
152.2.61.63 [05/Jan/2005:15:23:22 damnpissant
152.2.61.63 [05/Jan/2005:15:23:22 damnpissant
152.2.61.63 [05/Jan/2005:15:23:23 sonofabitch
152.2.61.63 [05/Jan/2005:15:23:23 sonofabitch
152.2.61.63 [05/Jan/2005:16:54:43 damnpissant
152.2.61.63 [05/Jan/2005:16:54:43 damnpissant
152.2.61.63 [05/Jan/2005:16:54:43 damnpissant
152.2.61.63 [05/Jan/2005:16:54:43 damnpissant
152.2.61.63 [05/Jan/2005:16:54:43 damnpissant
152.2.61.63 [05/Jan/2005:16:54:44 sonofabitch
152.2.61.63 [05/Jan/2005:16:54:44 sonofabitch
152.2.61.63 [05/Jan/2005:16:54:44 sonofabitch
152.2.61.63 [05/Jan/2005:16:54:44 sonofabitch
152.2.61.63 [05/Jan/2005:16:54:44 sonofabitch
152.2.61.63 [05/Jan/2005:16:54:44 sonofabitch
152.2.61.63 [05/Jan/2005:16:54:44 sonofabitch
152.2.61.63 [05/Jan/2005:16:54:44 sonofabitch
152.2.61.63 [05/Jan/2005:16:54:44 damnpissant
152.2.61.63 [05/Jan/2005:16:54:44 damnpissant

That's just one. Freaking things are all through the file. Very, very depressing, because now we have to figure out why the load balancer is switching certain users from machine to machine willy-nilly. One possible reason is that this particular user--for I know who it is-- started at 10, left the session open on her PC, came back at twelve, left, came back at three, and then again at four.

Blackboard, god love that poorly written piece of crap, should have closed her session automatically, but didn't. Still, that doesn't explain the load balancer wigging out and bouncing from machine to machine.

So now we go hunting for more information. Perhaps the cookies blackboard is using to track each user sessions are changing mid-session: though once again, they should not be. Right now I have no way of telling, as cookies are not being written to the logs.

So I need to create a custom log that does write out the cookies.

Two entries in the Apache config file take care of that

LogFormat "%h %t bloodyhell %{Cookie}i" cookie

and

CustomLog "|/usr/local/sbin/cronolog cookie" cookie


The "LogFormat" line defines the entry format for the custom log
%h - "host" In the vast majority of cases, this is the IP address of the user
%t - timestamp
bloodyhell - server name
%{Cookie}i" - Cookie
cookie - name of the customized format

Note that I've set the format to write out the information I need in the order I want it, plus the cookie. No more cutting or vi commands, though I will still need to sort and eyeball. It'll look like this;

24.163.116.72 [05/Jan/2005:23:55:29 -0500] bloodyhell session_id=@@b9bec8457e8b28c201325375bcee7093

The CustomLog line tells the web server to use a program called cronolog to write the custom log--we're calling it "cookie," using the pre-defined "cookie" format.

As you may have gathered, we're fond of cookies.

We're not real fond of Blackboard.

Posted by Bigwig at January 6, 2005 09:06 PM | TrackBack
Postscript:
First time visitor to House Hraka? Wondering if everything we produce could possibly be as brilliant/stupid/evil/pedantic/insipid/inspired as the post you just read? Check out the Hraka Essentials, the (mostly) reader-selected guide to Hraka's best posts, and decide for yourself.
Comments

Is the "Engrish" version just to make sure we're still reading at that point?

Posted by: MojoMark at January 6, 2005 11:23 PM

Next time try this. It looks a little funny since I want it to fit on the screen. It will run though.

cat accesslog1 accesslog2 accesslog3|\
awk '{print $1"\t"$4"\t"$2}'|\
sed 's/\[//' | sed 's/\.unc\.edu//'|\
sort|\
awk '{print $3"\t"$1"\t"$2}'|\
uniq -d -s 1|\
awk '{print $2"\t"$3"\t"$1}'

Posted by: GkBoy at January 6, 2005 11:25 PM

Silly question... to what extent is Blackboard tied into session functionality? If the user leaves and comes back and in the meantime a session reaches its TTL, then the system is working as designed.

Sounds plausible to me, anyway.

...But when the user comes back, it should start a new session on whatever machine and stick to THAT until the TTL is reached. This chain of events is not taking place, according to your massaged logs.

In all truth, I'm too tired to make sense of this right now.

Argh.

Posted by: ben at January 7, 2005 12:38 AM

That's it exactly, Mark.

Thanks, GK. I'll play around with that. Should have thought about awk and sed beforehand.

Blackboard is all about sessionality, Ben. From login to logout, everything is tied together. Time-outs seem to be screwing up, however. More when we figure it out.

Posted by: Bigwig at January 7, 2005 09:53 AM
Post a comment Note: Comments with more than two dashes per line will be blocked as spam.









Remember personal info?