From 946cd63e8ec05d6b4b975f1556ce1895ee463cd2 Mon Sep 17 00:00:00 2001 From: Rinze Date: Fri, 10 Jun 2016 10:32:32 +0200 Subject: [PATCH 1/3] Mail log management script cleanup --- management/mail_log.py | 245 ++++++++++++++++++++++++----------------- 1 file changed, 146 insertions(+), 99 deletions(-) diff --git a/management/mail_log.py b/management/mail_log.py index 22fb87af..8e6fec60 100755 --- a/management/mail_log.py +++ b/management/mail_log.py @@ -1,136 +1,183 @@ #!/usr/bin/python3 +import os.path +import re from collections import defaultdict -import re, os.path + import dateutil.parser import mailconfig import utils + def scan_mail_log(logger, env): - collector = { - "other-services": set(), - "imap-logins": { }, - "postgrey": { }, - "rejected-mail": { }, - "activity-by-hour": { "imap-logins": defaultdict(int), "smtp-sends": defaultdict(int) }, - } + """ Scan the system's mail log files and collect interesting data - collector["real_mail_addresses"] = set(mailconfig.get_mail_users(env)) | set(alias[0] for alias in mailconfig.get_mail_aliases(env)) + This function scans the 2 most recent mail log files in /var/log/. - for fn in ('/var/log/mail.log.1', '/var/log/mail.log'): - if not os.path.exists(fn): continue - with open(fn, 'rb') as log: - for line in log: - line = line.decode("utf8", errors='replace') - scan_mail_log_line(line.strip(), collector) + Args: + logger (ConsoleOutput): Object used for writing messages to the console + env (dict): Dictionary containing MiaB settings + """ - if collector["imap-logins"]: - logger.add_heading("Recent IMAP Logins") - logger.print_block("The most recent login from each remote IP adddress is show.") - for k in utils.sort_email_addresses(collector["imap-logins"], env): - for ip, date in sorted(collector["imap-logins"][k].items(), key = lambda kv : kv[1]): - logger.print_line(k + "\t" + str(date) + "\t" + ip) + collector = { + "other-services": set(), + "imap-logins": {}, + "postgrey": {}, + "rejected-mail": {}, + "activity-by-hour": { + "imap-logins": defaultdict(int), + "smtp-sends": defaultdict(int), + }, + "real_mail_addresses": ( + set(mailconfig.get_mail_users(env)) | set(alias[0] for alias in mailconfig.get_mail_aliases(env)) + ) + } - if collector["postgrey"]: - logger.add_heading("Greylisted Mail") - logger.print_block("The following mail was greylisted, meaning the emails were temporarily rejected. Legitimate senders will try again within ten minutes.") - logger.print_line("recipient" + "\t" + "received" + "\t" + "sender" + "\t" + "delivered") - for recipient in utils.sort_email_addresses(collector["postgrey"], env): - for (client_address, sender), (first_date, delivered_date) in sorted(collector["postgrey"][recipient].items(), key = lambda kv : kv[1][0]): - logger.print_line(recipient + "\t" + str(first_date) + "\t" + sender + "\t" + (("delivered " + str(delivered_date)) if delivered_date else "no retry yet")) + for fn in ('/var/log/mail.log.1', '/var/log/mail.log'): + if not os.path.exists(fn): + continue + with open(fn, 'rb') as log: + for line in log: + line = line.decode("utf8", errors='replace') + scan_mail_log_line(line.strip(), collector) - if collector["rejected-mail"]: - logger.add_heading("Rejected Mail") - logger.print_block("The following incoming mail was rejected.") - for k in utils.sort_email_addresses(collector["rejected-mail"], env): - for date, sender, message in collector["rejected-mail"][k]: - logger.print_line(k + "\t" + str(date) + "\t" + sender + "\t" + message) + if collector["imap-logins"]: + logger.add_heading("Recent IMAP Logins") + logger.print_block("The most recent login from each remote IP adddress is shown") + for k in utils.sort_email_addresses(collector["imap-logins"], env): + for ip, date in sorted(collector["imap-logins"][k].items(), key=lambda kv: kv[1]): + logger.print_line(k + "\t" + str(date) + "\t" + ip) - logger.add_heading("Activity by Hour") - for h in range(24): - logger.print_line("%d\t%d\t%d" % (h, collector["activity-by-hour"]["imap-logins"][h], collector["activity-by-hour"]["smtp-sends"][h] )) + if collector["postgrey"]: + logger.add_heading("Greylisted Mail") + logger.print_block("The following mail was greylisted, meaning the emails were temporarily rejected. " + "Legitimate senders will try again within ten minutes.") + logger.print_line("recipient" + "\t" + "received" + 3 * "\t" + "sender" + 6 * "\t" + "delivered") + for recipient in utils.sort_email_addresses(collector["postgrey"], env): + sorted_recipients = sorted(collector["postgrey"][recipient].items(), key=lambda kv: kv[1][0]) + for (client_address, sender), (first_date, delivered_date) in sorted_recipients: + logger.print_line( + recipient + "\t" + str(first_date) + "\t" + sender + "\t" + + (("delivered " + str(delivered_date)) if delivered_date else "no retry yet") + ) + + if collector["rejected-mail"]: + logger.add_heading("Rejected Mail") + logger.print_block("The following incoming mail was rejected.") + for k in utils.sort_email_addresses(collector["rejected-mail"], env): + for date, sender, message in collector["rejected-mail"][k]: + logger.print_line(k + "\t" + str(date) + "\t" + sender + "\t" + message) + + logger.add_heading("Activity by Hour") + for h in range(24): + logger.print_line( + "%d\t%d\t%d" % ( + h, + collector["activity-by-hour"]["imap-logins"][h], + collector["activity-by-hour"]["smtp-sends"][h] + ) + ) + + if len(collector["other-services"]) > 0: + logger.add_heading("Other") + logger.print_block("Unrecognized services in the log: " + ", ".join(collector["other-services"])) - if len(collector["other-services"]) > 0: - logger.add_heading("Other") - logger.print_block("Unrecognized services in the log: " + ", ".join(collector["other-services"])) def scan_mail_log_line(line, collector): - m = re.match(r"(\S+ \d+ \d+:\d+:\d+) (\S+) (\S+?)(\[\d+\])?: (.*)", line) - if not m: return + """ Scan a log line and extract interesting data """ - date, system, service, pid, log = m.groups() - date = dateutil.parser.parse(date) - - if service == "dovecot": - scan_dovecot_line(date, log, collector) + m = re.match(r"(\S+ \d+ \d+:\d+:\d+) (\S+) (\S+?)(\[\d+\])?: (.*)", line) - elif service == "postgrey": - scan_postgrey_line(date, log, collector) + if not m: + return - elif service == "postfix/smtpd": - scan_postfix_smtpd_line(date, log, collector) + date, system, service, pid, log = m.groups() + date = dateutil.parser.parse(date) - elif service == "postfix/submission/smtpd": - scan_postfix_submission_line(date, log, collector) + if service == "dovecot": + scan_dovecot_line(date, log, collector) + elif service == "postgrey": + scan_postgrey_line(date, log, collector) + elif service == "postfix/smtpd": + scan_postfix_smtpd_line(date, log, collector) + elif service == "postfix/submission/smtpd": + scan_postfix_submission_line(date, log, collector) + elif service in ("postfix/qmgr", "postfix/pickup", "postfix/cleanup", "postfix/scache", "spampd", "postfix/anvil", + "postfix/master", "opendkim", "postfix/lmtp", "postfix/tlsmgr"): + # nothing to look at + pass + else: + collector["other-services"].add(service) - elif service in ("postfix/qmgr", "postfix/pickup", "postfix/cleanup", - "postfix/scache", "spampd", "postfix/anvil", "postfix/master", - "opendkim", "postfix/lmtp", "postfix/tlsmgr"): - # nothing to look at - pass - else: - collector["other-services"].add(service) +def scan_dovecot_line(date, line, collector): + """ Scan a dovecot log line and extract interesting data """ + + m = re.match("imap-login: Login: user=<(.*?)>, method=PLAIN, rip=(.*?),", line) + + if m: + login, ip = m.group(1), m.group(2) + if ip != "127.0.0.1": # local login from webmail/zpush + collector["imap-logins"].setdefault(login, {})[ip] = date + collector["activity-by-hour"]["imap-logins"][date.hour] += 1 -def scan_dovecot_line(date, log, collector): - m = re.match("imap-login: Login: user=<(.*?)>, method=PLAIN, rip=(.*?),", log) - if m: - login, ip = m.group(1), m.group(2) - if ip != "127.0.0.1": # local login from webmail/zpush - collector["imap-logins"].setdefault(login, {})[ip] = date - collector["activity-by-hour"]["imap-logins"][date.hour] += 1 def scan_postgrey_line(date, log, collector): - m = re.match("action=(greylist|pass), reason=(.*?), (?:delay=\d+, )?client_name=(.*), client_address=(.*), sender=(.*), recipient=(.*)", log) - if m: - action, reason, client_name, client_address, sender, recipient = m.groups() - key = (client_address, sender) - if action == "greylist" and reason == "new": - collector["postgrey"].setdefault(recipient, {})[key] = (date, None) - elif action == "pass" and reason == "triplet found" and key in collector["postgrey"].get(recipient, {}): - collector["postgrey"][recipient][key] = (collector["postgrey"][recipient][key][0], date) + """ Scan a postgrey log line and extract interesting data """ + + m = re.match("action=(greylist|pass), reason=(.*?), (?:delay=\d+, )?client_name=(.*), client_address=(.*), " + "sender=(.*), recipient=(.*)", + log) + + if m: + action, reason, client_name, client_address, sender, recipient = m.groups() + key = (client_address, sender) + if action == "greylist" and reason == "new": + collector["postgrey"].setdefault(recipient, {})[key] = (date, None) + elif action == "pass" and reason == "triplet found" and key in collector["postgrey"].get(recipient, {}): + collector["postgrey"][recipient][key] = (collector["postgrey"][recipient][key][0], date) + def scan_postfix_smtpd_line(date, log, collector): - m = re.match("NOQUEUE: reject: RCPT from .*?: (.*?); from=<(.*?)> to=<(.*?)>", log) - if m: - message, sender, recipient = m.groups() - if recipient in collector["real_mail_addresses"]: - # only log mail to real recipients + """ Scan a postfix smtpd log line and extract interesting data """ - # skip this, is reported in the greylisting report - if "Recipient address rejected: Greylisted" in message: - return + m = re.match("NOQUEUE: reject: RCPT from .*?: (.*?); from=<(.*?)> to=<(.*?)>", log) - # simplify this one - m = re.search(r"Client host \[(.*?)\] blocked using zen.spamhaus.org; (.*)", message) - if m: - message = "ip blocked: " + m.group(2) + if m: + message, sender, recipient = m.groups() + if recipient in collector["real_mail_addresses"]: + # only log mail to real recipients - # simplify this one too - m = re.search(r"Sender address \[.*@(.*)\] blocked using dbl.spamhaus.org; (.*)", message) - if m: - message = "domain blocked: " + m.group(2) + # skip this, is reported in the greylisting report + if "Recipient address rejected: Greylisted" in message: + return + + # simplify this one + m = re.search(r"Client host \[(.*?)\] blocked using zen.spamhaus.org; (.*)", message) + if m: + message = "ip blocked: " + m.group(2) + + # simplify this one too + m = re.search(r"Sender address \[.*@(.*)\] blocked using dbl.spamhaus.org; (.*)", message) + if m: + message = "domain blocked: " + m.group(2) + + collector["rejected-mail"].setdefault(recipient, []).append((date, sender, message)) - collector["rejected-mail"].setdefault(recipient, []).append( (date, sender, message) ) def scan_postfix_submission_line(date, log, collector): - m = re.match("([A-Z0-9]+): client=(\S+), sasl_method=PLAIN, sasl_username=(\S+)", log) - if m: - procid, client, user = m.groups() - collector["activity-by-hour"]["smtp-sends"][date.hour] += 1 + """ Scan a postfix submission log line and extract interesting data """ + + m = re.match("([A-Z0-9]+): client=(\S+), sasl_method=PLAIN, sasl_username=(\S+)", log) + + if m: + # procid, client, user = m.groups() + collector["activity-by-hour"]["smtp-sends"][date.hour] += 1 + if __name__ == "__main__": - from status_checks import ConsoleOutput - env = utils.load_environment() - scan_mail_log(ConsoleOutput(), env) + from status_checks import ConsoleOutput + + env_vars = utils.load_environment() + scan_mail_log(ConsoleOutput(), env_vars) From ae1b56d23fe6c7f607cfe453dfbe861f95bf3805 Mon Sep 17 00:00:00 2001 From: Rinze Date: Fri, 10 Jun 2016 11:19:03 +0200 Subject: [PATCH 2/3] Added POP3 support to mail log management script --- management/mail_log.py | 25 +++++++++++++++++++------ 1 file changed, 19 insertions(+), 6 deletions(-) diff --git a/management/mail_log.py b/management/mail_log.py index 8e6fec60..427b8905 100755 --- a/management/mail_log.py +++ b/management/mail_log.py @@ -23,10 +23,12 @@ def scan_mail_log(logger, env): collector = { "other-services": set(), "imap-logins": {}, + "pop3-logins": {}, "postgrey": {}, "rejected-mail": {}, "activity-by-hour": { "imap-logins": defaultdict(int), + "pop3-logins": defaultdict(int), "smtp-sends": defaultdict(int), }, "real_mail_addresses": ( @@ -44,11 +46,18 @@ def scan_mail_log(logger, env): if collector["imap-logins"]: logger.add_heading("Recent IMAP Logins") - logger.print_block("The most recent login from each remote IP adddress is shown") + logger.print_block("The most recent login from each remote IP adddress is shown.") for k in utils.sort_email_addresses(collector["imap-logins"], env): for ip, date in sorted(collector["imap-logins"][k].items(), key=lambda kv: kv[1]): logger.print_line(k + "\t" + str(date) + "\t" + ip) + if collector["pop3-logins"]: + logger.add_heading("Recent POP3 Logins") + logger.print_block("The most recent login from each remote IP adddress is shown.") + for k in utils.sort_email_addresses(collector["pop3-logins"], env): + for ip, date in sorted(collector["pop3-logins"][k].items(), key=lambda kv: kv[1]): + logger.print_line(k + "\t" + str(date) + "\t" + ip) + if collector["postgrey"]: logger.add_heading("Greylisted Mail") logger.print_block("The following mail was greylisted, meaning the emails were temporarily rejected. " @@ -70,11 +79,14 @@ def scan_mail_log(logger, env): logger.print_line(k + "\t" + str(date) + "\t" + sender + "\t" + message) logger.add_heading("Activity by Hour") + logger.print_block("Logins and sent mail per hour.") + logger.print_block("Hour\tIMAP\tPOP3\tSent") for h in range(24): logger.print_line( - "%d\t%d\t%d" % ( + "%d\t%d\t\t%d\t\t%d" % ( h, collector["activity-by-hour"]["imap-logins"][h], + collector["activity-by-hour"]["pop3-logins"][h], collector["activity-by-hour"]["smtp-sends"][h] ) ) @@ -114,13 +126,14 @@ def scan_mail_log_line(line, collector): def scan_dovecot_line(date, line, collector): """ Scan a dovecot log line and extract interesting data """ - m = re.match("imap-login: Login: user=<(.*?)>, method=PLAIN, rip=(.*?),", line) + m = re.match("(imap|pop3)-login: Login: user=<(.*?)>, method=PLAIN, rip=(.*?),", line) if m: - login, ip = m.group(1), m.group(2) + prot, login, ip = m.group(1), m.group(2), m.group(3) + logins_key = "%s-logins" % prot if ip != "127.0.0.1": # local login from webmail/zpush - collector["imap-logins"].setdefault(login, {})[ip] = date - collector["activity-by-hour"]["imap-logins"][date.hour] += 1 + collector[logins_key].setdefault(login, {})[ip] = date + collector["activity-by-hour"][logins_key][date.hour] += 1 def scan_postgrey_line(date, log, collector): From 1c84e0aeb65e7a557d003972e3660148af416750 Mon Sep 17 00:00:00 2001 From: Rinze Date: Fri, 10 Jun 2016 13:08:57 +0200 Subject: [PATCH 3/3] Added received mail count to hourly activity overview in mail log management script --- management/mail_log.py | 25 ++++++++++++++++++++----- 1 file changed, 20 insertions(+), 5 deletions(-) diff --git a/management/mail_log.py b/management/mail_log.py index 427b8905..0a9d5099 100755 --- a/management/mail_log.py +++ b/management/mail_log.py @@ -30,6 +30,7 @@ def scan_mail_log(logger, env): "imap-logins": defaultdict(int), "pop3-logins": defaultdict(int), "smtp-sends": defaultdict(int), + "smtp-receives": defaultdict(int), }, "real_mail_addresses": ( set(mailconfig.get_mail_users(env)) | set(alias[0] for alias in mailconfig.get_mail_aliases(env)) @@ -79,15 +80,16 @@ def scan_mail_log(logger, env): logger.print_line(k + "\t" + str(date) + "\t" + sender + "\t" + message) logger.add_heading("Activity by Hour") - logger.print_block("Logins and sent mail per hour.") - logger.print_block("Hour\tIMAP\tPOP3\tSent") + logger.print_block("Dovecot logins and Postfix mail traffic per hour.") + logger.print_block("Hour\tIMAP\tPOP3\tSent\tReceived") for h in range(24): logger.print_line( - "%d\t%d\t\t%d\t\t%d" % ( + "%d\t%d\t\t%d\t\t%d\t\t%d" % ( h, collector["activity-by-hour"]["imap-logins"][h], collector["activity-by-hour"]["pop3-logins"][h], - collector["activity-by-hour"]["smtp-sends"][h] + collector["activity-by-hour"]["smtp-sends"][h], + collector["activity-by-hour"]["smtp-receives"][h], ) ) @@ -113,6 +115,8 @@ def scan_mail_log_line(line, collector): scan_postgrey_line(date, log, collector) elif service == "postfix/smtpd": scan_postfix_smtpd_line(date, log, collector) + elif service == "postfix/cleanup": + scan_postfix_cleanup_line(date, log, collector) elif service == "postfix/submission/smtpd": scan_postfix_submission_line(date, log, collector) elif service in ("postfix/qmgr", "postfix/pickup", "postfix/cleanup", "postfix/scache", "spampd", "postfix/anvil", @@ -155,6 +159,8 @@ def scan_postgrey_line(date, log, collector): def scan_postfix_smtpd_line(date, log, collector): """ Scan a postfix smtpd log line and extract interesting data """ + # Check if the incomming mail was rejected + m = re.match("NOQUEUE: reject: RCPT from .*?: (.*?); from=<(.*?)> to=<(.*?)>", log) if m: @@ -162,7 +168,7 @@ def scan_postfix_smtpd_line(date, log, collector): if recipient in collector["real_mail_addresses"]: # only log mail to real recipients - # skip this, is reported in the greylisting report + # skip this, if reported in the greylisting report if "Recipient address rejected: Greylisted" in message: return @@ -179,6 +185,15 @@ def scan_postfix_smtpd_line(date, log, collector): collector["rejected-mail"].setdefault(recipient, []).append((date, sender, message)) +def scan_postfix_cleanup_line(date, _, collector): + """ Scan a postfix cleanup log line and extract interesting data + + It is assumed that every log of postfix/cleanup indicates an email that was successfulfy received by Postfix. + + """ + + collector["activity-by-hour"]["smtp-receives"][date.hour] += 1 + def scan_postfix_submission_line(date, log, collector): """ Scan a postfix submission log line and extract interesting data """