January 2014

Gavin Pickin

Dev Ops - From Mail Logs to DB Stats in a CFML Dashboard - Part 2

Server Admin

In the first post in this series, I mentioned that lately I have had a lot more Dev Ops duties than in the past. I am sharing my process as I try and solve a problem, keeping up with our qmail Mail Logs, to look for potential risky behavior, because our Servers get blacklisted. I'm using a few technologies, with the end goal, getting the log data in a useable format for ColdFusion / Railo CFML to crunch the data, and make it look pretty in a CFML Dashboard. Read the first post here to get up to speed.

We left off looking at 2 lines in the logs

Jan 28 21:32:14 independence smtp-mx: 1390973534.709575 CHKUSER rejected relaying: 
from <> remote <> 
rcpt <> : client not allowed to relay


Someone trying to use us to relay to one of our Internal Email Accounts… note the smtp-mx.
Compared to below, which is smtp, someone trying to use our server to relay to an external address.

Jan 28 21:19:10 independence smtp: 1390972750.741663 CHKUSER rejected relaying: 
from <> remote <> 
rcpt <> : client not allowed to relay


So, to make this process successful, we need to identify the other lines of the log files that we are interested in. I ran a grep over 5-6 weeks of logs, and I found almost 10 million lines in the logs. A lot of that is garbage, that won't need, so lets keep diving in and see what else we can find.

There seem to be a lot of lines like the following

Dec 29 17:28:26 independence smtp-mx: 1388366906.766843 CHKUSER accepted sender: 
from <> remote <> 
rcpt <> : sender accepted
Dec 29 17:27:33 independence smsp: 1388366853.473529 CHKUSER accepted sender: 
from <> remote <> 
rcpt <> : accepted any sender always


Looking at the patterns, it looks like the system uses CHKUSER accepted/rejected and rcp or sender. The sender lines seem to just decide if the sender is legit or not, but the real action is where the rcp is. So, I think we can ignore any lines with 'sender:' in them.

Lets grep that, and see what we have left.

Dec 29 17:26:47 independence smsp: 1388366807.747284 CHKUSER relaying rcpt: 
from <> remote <> 
rcpt <> : client allowed to relay


Looking at this line, we see "client allowed to relay", so lets try and see why. The user is sending as, and is authenticating as… those are both our domains, so this is a successful authentication. The user is sending as a user other than themselves though, and after further study, is one of the authenticating emails used by one of our cfml servers. 

Lets look for some CHKUSER relaying rcpt: where the sender and the authenticating email is the same.

Dec 29 17:02:20 independence smtp: 1388365340.829794 CHKUSER relaying rcpt: 
from <> remote <> 
rcpt <> : client allowed to relay


This line shows a relaying success, with the name sender as the authenticator. The service is not smtp not smsp, so maybe that is a factor in distinguishing them… but the rest of the log looks the same.
Lets look and see if we can get CHKUSER relaying without the 'sender:' and with no authenticating email address '::> remote' and when we grep that, what do we get.

Dec 30 18:26:49 independence smtp: 1388456809.555333 CHKUSER relaying rcpt: 
from <> remote <> 
rcpt <> : client allowed to relay


So now we have identified what counts as a successful authenticated message, but based on being from webmail.

It seems like every match we have, includes the CHKUSER… without "sender:". Are we missing anything? Lets run a grep on the logs excluding CHKUSER and see what we have. I'll save you looking at a pile of mess, but the short of it… unless we care about connections, logins, logouts, spam and rbl checks, we can probably rule out anything without CHKUSER. There is still a lot of good stuff with CHKUSER that we haven't touched on yet. It seems to track all messages received by accounts as well as the sending information we've been focusing on. 

So making an executive decision, I think I want to keep all log lines with CHKUSER, but maybe without the SENDER.
Lets do some counts, and see how many rows we get with and without the "sender:".

#grep CHKUSER mail* | grep -c 'CHKUSER'

# grep CHKUSER mail* | grep -c -v 'sender:'


So removing those sender items drops the count in half, and is not about 15% of the total number of log lines. And we still have room to grow… so I am pretty happy with this process. Lets wrap all the files together, into one big log, and check the file size. 350mb… down a lot from the initial 2.5gb… and this is 5-6 weeks of logs, so this will be much smaller on a week to week basis.

So, now we know what we want out of the log files… so lets setup the process of getting the logs moved, and get the "goods" out of them… and in a position for our CFML Agent to do its job. As I mentioned in our previous post, we want to keep separation of duties on the servers, so we have Server A with Mail running, and the log files… and we want to move them to Server B… massage them, and prep them for CFML. 

Check back soon, because next we will setup our cron jobs on Server A.


Blog Search