Tuesday, August 21, 2007

SMTP Log parsing


From time to time I need to check my IIs SMTP log files to find why a particular user didn't get email notifications. I have several web servers running community web applications that sends tips, notifications and newsletter to subscribed users.

Digging into SMTP logs is a time consuming process. In addition, The SMTP service sends hundreds of emails and tracking a specific session can be quiet a challenge.

I found that a session can be scattered around the log in a non-consecutive order. I needed a way to collect, group and display SMTP sessions lines in a way that I can see the session flow along with its SMTP verbs.

The natural candidate for log parsing was Microsoft's LogParser 2.2. Boy, this tool is something. After experimenting with log parser I automated the process via PowerShell.

The script query's SMTP log files, in W3C format, and displays the output for all sessions per server IP it finds or for the email address specified in $smtpAddress parameter. I added the option to show all sessions in order to find additional error messages occurred for the queried server.

 

 

############# Parse-W3C.ps1 ###############

param(
    [string]$smtpAddress = $(throw "Please specify email address"),
    [string]$log = $(throw "Please specify log file path, accepts wildcard")
)

#cls
$smtpAddress = "TO:<$smtpAddress>";

 

# the user may have more than one server associated, get list of all mail servers ips
$query="SELECT DISTINCT c-ip FROM $log WHERE cs-uri-query LIKE '%$smtpAddress%'";

$ips = logparser -i:W3C -q:ON $query;

if($ips.length -eq 0){
    write-host "Address not found.`n" -b black -f red;
    return;
}

 

# foreach ip returned emit the session

$ips | foreach {

    $query = "SELECT date,time,c-ip,cs-method,cs-uri-query FROM $log WHERE c-ip = '$_'";
    write-host "[QUERY] $query" -b black -f green;

    $lp=logparser -i:W3C -q:ON $query;


    # set start anchors where line matches "220+" (session starts)
    $session=@();   
    for($i=0;$i -le $lp.length;$i++){if($lp[$i] -match "-\s+220\+"){$session+=$i}}
    $session+=$lp.length;

    if($session.length -eq 0){
        write-host "`nNo sessions found for <$_>`n" -b black -f red;
        return;
    }

    $key = read-host "Found $($session.length) sessions for <$_>`n.Display All Sessions [A], User Sessions [U]?";
    write-host;

    for($i=0;$i -lt $session.length-1;$i++){
        # slice array
        $tmpArr = $lp[$session[$i]..$($session[$i+1]-1)];


        # regex to match any of 421,450,451,452,500,501,
        # 502,503,504,550,551,552,553,554 smtp error codes
        $regex =  "(-\s+)?(421|45[0-2]|5(0|5)[0-4])\+";


        # generic code to colorize SMTP errors
        [scriptblock]$paintRow = {
            $tmpArr | % {
                $email = [regex]::match($_,$smtpAddress).success;
                $err = [regex]::match($_,$regex).success;
                if($email){
                    if($err){write-host $_ -f red -b black}
                    else{write-host $_ -f yellow -b black}
                }
                elseif($err){write-host $_ -f red -b black}               
                else{$_}
            }
        }

        if($tmpArr -match $smtpAddress -and $key -eq "u"){
            & $paintRow;
            if($i -eq 0){read-host "`nPress <ENTER> key to continue"} else{write-host}
        }           
        elseif($key -eq "a"){
            & $paintRow;
            if($i -lt $session.length-2){read-host "`nPress <ENTER> key to continue"} else{write-host}
        }
    }
}

 

###########################################

 

Hope you'll find it useful.


Shay

6 comments:

marco.shaw said...

Supercool! I like how you've used the tools to come back and customize the coloring of the lines!

Eric Hazen said...

How do you start the script?

Mike said...

Hey buddy, thanks very much for this, i found it incredibly useful.

phreakhead said...

Hi, I based a bounce counter program on this post, only to find out later that this method doesn't actually work for high-volume senders because SMTP logs are not in linear sequential order. There's more about it in my blog post: Email Bounce Detection in SMTP Logs and Why It Is Impossible.

Michael McNally said...

Here it is 9 years later and I still can't find a better or easier tool for gathering this information from a Windows SMTP log.

I'm fairly comfortable with PowerShell, though not at all an expert. I discovered that when running this from a 64 bit server, I needed to specify the explicit path to logparser.exe, since it is in Program Files(x86) folder. Most likely, there is more than one way to do this, but I went with:

$ips = '"C:\Program Files (x86)\Log Parser 2.2\logparser" -i:W3C -q:ON $query';

This needs to be modified in the foreach loop also.

That much is all well and good. However, when I run the script and feed it an address, I get prompted:
Found 1 sessions for <"C:\Program Files (x86)\Log Parser 2.2\logparser" -i:W3C -q:ON $query>.Display All Sessions [A], User Sessions [U]?:

Then, no matter whether I enter A or U, I get no result displayed. What's the fix for that?

Anonymous said...

Yes, that's very useful yet.

Michael, I follow your suggestion but, for some reason, it doesn't work. No result displayed. I included "C:\Program Files (x86)\Log Parser 2.2" in the PATH environment variable and now I can see the log as expected.

Eri