"""

pcres.log is the logfile by the Envisionware PC Reservation server

iii.log prepared via:

cat pcres.log |grep "Getting patron record for\|Patron record retrieved for" > iii.log

pcres.log, among other things, contains lines like:
2012/07/16 14:30.35 [Thread 0x00000874] (2031) Getting patron record for:  [redacted]
2012/07/16 14:31.07 [Thread 0x00000874] (2032) Patron record retrieved for: [redacted]

These lines may be next to eachother in sequence, or they may be separated by similar
output from other threads (differentiated by the [Thread 0xID])

Script follows, reads in iii.log, matches each (2031) line to its corresponding (2032)
line (that is, getting vs received) and subtracts the timestamps to give a lookup time.

output can be parsed for instance through "|sort |uniq -c" afterward.

"""

f = open('iii.log', 'r')

q = {}
for line in f.readlines():
    parts = line.split(" ")
    if (parts[4] == "(2031)"):
        # threadid, barcode, time
        # print parts[3], parts[10], parts[1]

        q[(parts[3], parts[10])] = parts[1]

    if (parts[4] == "(2032)"):
        #print q[(parts[3], parts[10])], parts[1]

        then = q[(parts[3], parts[10])]
        now = parts[1]

        then = then.replace(":", ".")
        now = now.replace(":", ".")

        then = then.split(".")
        now = now.split(".")

        then = (int(then[0]) * 3600) + (int(then[1]) * 60) + int(then[2])
        now = (int(now[0]) * 3600) + (int(now[1]) * 60) + int(now[2])

        print now - then

        del q[(parts[3], parts[10])]

    #print "interleaved: %d" % (len(q))