Ellipsis

I love it when 82 characters do a ton of work for me.

Today I’m trying to debug Courier-IMAP ssl errors that are reported in the log file as “DEBUG: Unexpected SSL connection shutdown”. We’re using QMail so the times in the log file are in tai64, and I’m using Eric Rescorla’s SSLDump:”http://www.rtfm.com/ssldump/” to debug the SSL traffic, which reports time in epoch seconds. I’d like to correlate the SSL traffic with the logged errors. Here’s how:

In window 1, I monitor the QMail logs with:

tail -f /var/log/qmail/imap4-ssl/current | tail64nlocal

which gives output like:

2007-10-30 06:26:02.322254500 tcpserver: status: 30/40
2007-10-30 06:26:02.322255500 tcpserver: pid 9635 from 1.2.3.4
2007-10-30 06:26:02.322257500 tcpserver: ok 9635 buzz.example.net:10.1.1.20:993 :216.220.209.17::57693
2007-10-30 06:26:02.439369500 DEBUG: Connection, ip=[1.2.3.4]

In window 2, I monitor the SSL traffic with:

sudo ssldump -e -k imap.example.com.pem  port 993 | ~/bin/epoch2local.rb

where the script @epoch2local.rb is:

#!/usr/bin/ruby -p

$_.sub!(/1\d{9}/) { |t| Time.at(t.to_f).strftime("%Y-%m-%d %H:%M:%S") }

A quick dissection:

• ruby -p places your code in a while gest; ....; print; end loop
• $_ is the current line
• .sub! does in place substitution, changing the value of $_
• sub!(pattern) { |match| block } the string matting pattern is passed into the {} block as the variable match. The result from the block is substituted for the original string
• /1\d{9}/: assume that a 10-digit number starting with 1 is the epoch time (true for another 30 years or so)
• |t| Time.at(t.to_f).strftime("%Y-%m-%d %H:%M:%S") : PFM. No, not really. Pass the match into the block as t. Convert to a float, then a Time value, then format as %Y-%m-%d %H:%M:%S

I then get SSLDump out put as:

23 21 2007-10-30 06:41:19.1945 (0.1309)  C>S  application_data
24 3  2007-10-30 06:41:19.2474 (0.1185)  S>C  Handshake
      Certificate
24 4  2007-10-30 06:41:19.2474 (0.0000)  S>C  Handshake
      ServerHelloDone  

And I can match up the times with the QMail logs. Fini (although I still have the original question to resolve)