mailinabox/management/mail_log.py

#!/usr/bin/python3

import os.path
import re
from collections import defaultdict

import dateutil.parser

import mailconfig
import utils


def scan_mail_log(logger, env):
    """ Scan the system's mail log files and collect interesting data

    This function scans the 2 most recent mail log files in /var/log/.

    Args:
        logger (ConsoleOutput): Object used for writing messages to the console
        env (dict): Dictionary containing MiaB settings
    """

    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),
            "smtp-receives": defaultdict(int),
        },
        "real_mail_addresses": (
            set(mailconfig.get_mail_users(env)) | set(alias[0] for alias in mailconfig.get_mail_aliases(env))
        )
    }

    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["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)

    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. "
                           "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")
    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\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-receives"][h],
            )
        )

    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):
    """ Scan a log line and extract interesting data """

    m = re.match(r"(\S+ \d+ \d+:\d+:\d+) (\S+) (\S+?)(\[\d+\])?: (.*)", line)

    if not m:
        return

    date, system, service, pid, log = m.groups()
    date = dateutil.parser.parse(date)

    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/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",
                     "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|pop3)-login: Login: user=<(.*?)>, method=PLAIN, rip=(.*?),", line)

    if m:
        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[logins_key].setdefault(login, {})[ip] = date
        collector["activity-by-hour"][logins_key][date.hour] += 1


def scan_postgrey_line(date, log, collector):
    """ 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):
    """ 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:
        message, sender, recipient = m.groups()
        if recipient in collector["real_mail_addresses"]:
            # only log mail to real recipients

            # skip this, if 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))


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 """

    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_vars = utils.load_environment()
    scan_mail_log(ConsoleOutput(), env_vars)