plugins/mail-log/mail-log-plugin.c

/* Copyright (c) 2007-2018 Dovecot authors, see the included COPYING file */

#include "lib.h"
#include "array.h"
#include "llist.h"
#include "str.h"
#include "str-sanitize.h"
#include "imap-util.h"
#include "mail-user.h"
#include "mail-storage-private.h"
#include "notify-plugin.h"
#include "mail-log-plugin.h"


#define MAILBOX_NAME_LOG_LEN 64
#define HEADER_LOG_LEN 80

#define MAIL_LOG_USER_CONTEXT(obj) \
    MODULE_CONTEXT_REQUIRE(obj, mail_log_user_module)

enum mail_log_field {
    MAIL_LOG_FIELD_UID  = 0x01,
    MAIL_LOG_FIELD_BOX  = 0x02,
    MAIL_LOG_FIELD_MSGID    = 0x04,
    MAIL_LOG_FIELD_PSIZE    = 0x08,
    MAIL_LOG_FIELD_VSIZE    = 0x10,
    MAIL_LOG_FIELD_FLAGS    = 0x20,
    MAIL_LOG_FIELD_FROM = 0x40,
    MAIL_LOG_FIELD_SUBJECT  = 0x80
};
#define MAIL_LOG_DEFAULT_FIELDS \
    (MAIL_LOG_FIELD_UID | MAIL_LOG_FIELD_BOX | \
     MAIL_LOG_FIELD_MSGID | MAIL_LOG_FIELD_PSIZE)

enum mail_log_event {
    MAIL_LOG_EVENT_DELETE       = 0x01,
    MAIL_LOG_EVENT_UNDELETE     = 0x02,
    MAIL_LOG_EVENT_EXPUNGE      = 0x04,
    MAIL_LOG_EVENT_SAVE     = 0x08,
    MAIL_LOG_EVENT_COPY     = 0x10,
    MAIL_LOG_EVENT_MAILBOX_CREATE   = 0x20,
    MAIL_LOG_EVENT_MAILBOX_DELETE   = 0x40,
    MAIL_LOG_EVENT_MAILBOX_RENAME   = 0x80,
    MAIL_LOG_EVENT_FLAG_CHANGE  = 0x100
};
#define MAIL_LOG_DEFAULT_EVENTS \
    (MAIL_LOG_EVENT_DELETE | MAIL_LOG_EVENT_UNDELETE | \
     MAIL_LOG_EVENT_EXPUNGE | MAIL_LOG_EVENT_SAVE | MAIL_LOG_EVENT_COPY | \
     MAIL_LOG_EVENT_MAILBOX_DELETE | MAIL_LOG_EVENT_MAILBOX_RENAME)

static const char *field_names[] = {
    "uid",
    "box",
    "msgid",
    "size",
    "vsize",
    "flags",
    "from",
    "subject",
    NULL
};

static const char *event_names[] = {
    "delete",
    "undelete",
    "expunge",
    "save",
    "copy",
    "mailbox_create",
    "mailbox_delete",
    "mailbox_rename",
    "flag_change",
    NULL
};

struct mail_log_user {
    union mail_user_module_context module_ctx;

    enum mail_log_field fields;
    enum mail_log_event events;
    bool cached_only;
};

struct mail_log_message {
    struct mail_log_message *prev, *next;

    enum mail_log_event event;
    bool ignore;
    const char *pretext, *text;
};

struct mail_log_mail_txn_context {
    pool_t pool;
    struct mail_log_message *messages, *messages_tail;
};

static MODULE_CONTEXT_DEFINE_INIT(mail_log_user_module,
                  &mail_user_module_register);

static enum mail_log_field mail_log_field_find(const char *name)
{
    unsigned int i;

    for (i = 0; field_names[i] != NULL; i++) {
        if (strcmp(name, field_names[i]) == 0)
            return 1 << i;
    }
    return 0;
}

static enum mail_log_event mail_log_event_find(const char *name)
{
    unsigned int i;

    if (strcmp(name, "append") == 0) {
        /* v1.x backwards compatibility */
        name = "save";
    }
    for (i = 0; event_names[i] != NULL; i++) {
        if (strcmp(name, event_names[i]) == 0)
            return 1 << i;
    }
    return 0;
}

static enum mail_log_field mail_log_parse_fields(const char *str)
{
    const char *const *tmp;
    static enum mail_log_field field, fields = 0;

    for (tmp = t_strsplit_spaces(str, ", "); *tmp != NULL; tmp++) {
        field = mail_log_field_find(*tmp);
        if (field == 0)
            i_fatal("Unknown field in mail_log_fields: '%s'", *tmp);
        fields |= field;
    }
    return fields;
}

static enum mail_log_event mail_log_parse_events(const char *str)
{
    const char *const *tmp;
    static enum mail_log_event event, events = 0;

    for (tmp = t_strsplit_spaces(str, ", "); *tmp != NULL; tmp++) {
        event = mail_log_event_find(*tmp);
        if (event == 0)
            i_fatal("Unknown event in mail_log_events: '%s'", *tmp);
        events |= event;
    }
    return events;
}

static void mail_log_mail_user_created(struct mail_user *user)
{
    struct mail_log_user *muser;
    const char *str;

    muser = p_new(user->pool, struct mail_log_user, 1);
    MODULE_CONTEXT_SET(user, mail_log_user_module, muser);

    str = mail_user_plugin_getenv(user, "mail_log_fields");
    muser->fields = str == NULL ? MAIL_LOG_DEFAULT_FIELDS :
        mail_log_parse_fields(str);

    str = mail_user_plugin_getenv(user, "mail_log_events");
    muser->events = str == NULL ? MAIL_LOG_DEFAULT_EVENTS :
        mail_log_parse_events(str);

    muser->cached_only =
        mail_user_plugin_getenv_bool(user, "mail_log_cached_only");
}

static void mail_log_append_mailbox_name(string_t *str, struct mail *mail)
{
    const char *mailbox_str;

    mailbox_str = mailbox_get_vname(mail->box);
    str_printfa(str, "box=%s",
            str_sanitize(mailbox_str, MAILBOX_NAME_LOG_LEN));
}

static void
mail_log_append_mail_header(string_t *str, struct mail *mail,
                const char *name, const char *header)
{
    const char *value;

    if (mail_get_first_header_utf8(mail, header, &value) <= 0)
        value = "";
    str_printfa(str, "%s=%s", name, str_sanitize(value, HEADER_LOG_LEN));
}

static void
mail_log_append_uid(struct mail_log_mail_txn_context *ctx,
            struct mail_log_message *msg, string_t *str, uint32_t uid)
{
    if (uid != 0)
        str_printfa(str, "uid=%u", uid);
    else {
        /* we don't know the uid yet, assign it later */
        str_printfa(str, "uid=");
        msg->pretext = p_strdup(ctx->pool, str_c(str));
        str_truncate(str, 0);
    }
}

static void
mail_log_update_wanted_fields(struct mail *mail, enum mail_log_field fields)
{
    enum mail_fetch_field wanted_fields = 0;
    struct mailbox_header_lookup_ctx *wanted_headers = NULL;
    const char *headers[4];
    unsigned int hdr_idx = 0;

    if ((fields & MAIL_LOG_FIELD_MSGID) != 0)
        headers[hdr_idx++] = "Message-ID";
    if ((fields & MAIL_LOG_FIELD_FROM) != 0)
        headers[hdr_idx++] = "From";
    if ((fields & MAIL_LOG_FIELD_SUBJECT) != 0)
        headers[hdr_idx++] = "Subject";
    if (hdr_idx > 0) {
        i_assert(hdr_idx < N_ELEMENTS(headers));
        headers[hdr_idx] = NULL;
        wanted_headers = mailbox_header_lookup_init(mail->box, headers);
    }

    if ((fields & MAIL_LOG_FIELD_PSIZE) != 0)
        wanted_fields |= MAIL_FETCH_PHYSICAL_SIZE;
    if ((fields & MAIL_LOG_FIELD_VSIZE) != 0)
        wanted_fields |= MAIL_FETCH_VIRTUAL_SIZE;

    mail_add_temp_wanted_fields(mail, wanted_fields, wanted_headers);
    mailbox_header_lookup_unref(&wanted_headers);
}

static void
mail_log_append_mail_message_real(struct mail_log_mail_txn_context *ctx,
                  struct mail *mail, enum mail_log_event event,
                  const char *desc)
{
    struct mail_log_user *muser =
        MAIL_LOG_USER_CONTEXT(mail->box->storage->user);
    struct mail_log_message *msg;
    string_t *text;
    uoff_t size;

    msg = p_new(ctx->pool, struct mail_log_message, 1);

    /* avoid parsing through the message multiple times */
    mail_log_update_wanted_fields(mail, muser->fields);

    text = t_str_new(128);
    str_append(text, desc);
    str_append(text, ": ");
    if ((muser->fields & MAIL_LOG_FIELD_BOX) != 0) {
        mail_log_append_mailbox_name(text, mail);
        str_append(text, ", ");
    }
    if ((muser->fields & MAIL_LOG_FIELD_UID) != 0) {
        if (event != MAIL_LOG_EVENT_SAVE &&
            event != MAIL_LOG_EVENT_COPY)
            mail_log_append_uid(ctx, msg, text, mail->uid);
        else {
            /* with mbox mail->uid contains the uid, but handle
               this consistently with all mailbox formats */
            mail_log_append_uid(ctx, msg, text, 0);
        }
        /* make sure UID is assigned to this mail */
        mail->transaction->flags |= MAILBOX_TRANSACTION_FLAG_ASSIGN_UIDS;
        str_append(text, ", ");
    }
    if ((muser->fields & MAIL_LOG_FIELD_MSGID) != 0) {
        mail_log_append_mail_header(text, mail, "msgid", "Message-ID");
        str_append(text, ", ");
    }
    if ((muser->fields & MAIL_LOG_FIELD_PSIZE) != 0) {
        if (mail_get_physical_size(mail, &size) == 0)
            str_printfa(text, "size=%"PRIuUOFF_T, size);
        else
            str_printfa(text, "size=error");
        str_append(text, ", ");
    }
    if ((muser->fields & MAIL_LOG_FIELD_VSIZE) != 0) {
        if (mail_get_virtual_size(mail, &size) == 0)
            str_printfa(text, "vsize=%"PRIuUOFF_T, size);
        else
            str_printfa(text, "vsize=error");
        str_append(text, ", ");
    }
    if ((muser->fields & MAIL_LOG_FIELD_FROM) != 0) {
        mail_log_append_mail_header(text, mail, "from", "From");
        str_append(text, ", ");
    }
    if ((muser->fields & MAIL_LOG_FIELD_SUBJECT) != 0) {
        mail_log_append_mail_header(text, mail, "subject", "Subject");
        str_append(text, ", ");
    }
    if ((muser->fields & MAIL_LOG_FIELD_FLAGS) != 0) {
        str_printfa(text, "flags=(");
        imap_write_flags(text, mail_get_flags(mail),
                 mail_get_keywords(mail));
        str_append(text, "), ");
    }
    str_truncate(text, str_len(text)-2);

    msg->event = event;
    msg->text = p_strdup(ctx->pool, str_c(text));
    DLLIST2_APPEND(&ctx->messages, &ctx->messages_tail, msg);
}

static void mail_log_add_dummy_msg(struct mail_log_mail_txn_context *ctx,
                   enum mail_log_event event)
{
    struct mail_log_message *msg;

    msg = p_new(ctx->pool, struct mail_log_message, 1);
    msg->event = event;
    msg->ignore = TRUE;
    DLLIST2_APPEND(&ctx->messages, &ctx->messages_tail, msg);
}

static void
mail_log_append_mail_message(struct mail_log_mail_txn_context *ctx,
                 struct mail *mail, enum mail_log_event event,
                 const char *desc)
{
    struct mail_log_user *muser =
        MAIL_LOG_USER_CONTEXT(mail->box->storage->user);

    if ((muser->events & event) == 0) {
        if (event == MAIL_LOG_EVENT_SAVE ||
            event == MAIL_LOG_EVENT_COPY)
            mail_log_add_dummy_msg(ctx, event);
        return;
    }

    T_BEGIN {
        enum mail_lookup_abort orig_lookup_abort = mail->lookup_abort;

        if (event != MAIL_LOG_EVENT_SAVE && muser->cached_only)
            mail->lookup_abort = MAIL_LOOKUP_ABORT_NOT_IN_CACHE;
        mail_log_append_mail_message_real(ctx, mail, event, desc);
        mail->lookup_abort = orig_lookup_abort;
    } T_END;
}

static void *
mail_log_mail_transaction_begin(struct mailbox_transaction_context *t ATTR_UNUSED)
{
    pool_t pool;
    struct mail_log_mail_txn_context *ctx;

    pool = pool_alloconly_create("mail-log", 2048);
    ctx = p_new(pool, struct mail_log_mail_txn_context, 1);
    ctx->pool = pool;
    return ctx;
}

static void mail_log_mail_save(void *txn, struct mail *mail)
{
    struct mail_log_mail_txn_context *ctx =
        (struct mail_log_mail_txn_context *)txn;

    mail_log_append_mail_message(ctx, mail, MAIL_LOG_EVENT_SAVE, "save");
}

static void mail_log_mail_copy(void *txn, struct mail *src, struct mail *dst)
{
    struct mail_log_mail_txn_context *ctx =
        (struct mail_log_mail_txn_context *)txn;
    struct mail_private *src_pmail = (struct mail_private *)src;
    struct mailbox *src_box = src->box;
    const char *desc;

    if (src_pmail->vmail != NULL) {
        /* copying a mail from virtual storage. src points to the
           backend mail, but we want to log the virtual mailbox name. */
        src_box = src_pmail->vmail->box;
    }
    desc = t_strdup_printf("copy from %s",
                   str_sanitize(mailbox_get_vname(src_box),
                        MAILBOX_NAME_LOG_LEN));
    mail_log_append_mail_message(ctx, dst,
                     MAIL_LOG_EVENT_COPY, desc);
}

static void mail_log_mail_expunge(void *txn, struct mail *mail)
{
    struct mail_log_mail_txn_context *ctx =
        (struct mail_log_mail_txn_context *)txn;
    struct mail_private *p = (struct mail_private*)mail;

    mail_log_append_mail_message(ctx, mail, MAIL_LOG_EVENT_EXPUNGE,
                     p->autoexpunged ? "autoexpunge" : "expunge");
}

static void mail_log_mail_update_flags(void *txn, struct mail *mail,
                       enum mail_flags old_flags)
{
    struct mail_log_mail_txn_context *ctx =
        (struct mail_log_mail_txn_context *)txn;
    enum mail_flags new_flags = mail_get_flags(mail);

    if (((old_flags ^ new_flags) & MAIL_DELETED) == 0) {
        mail_log_append_mail_message(ctx, mail,
                         MAIL_LOG_EVENT_FLAG_CHANGE,
                         "flag_change");
    } else if ((old_flags & MAIL_DELETED) == 0) {
        mail_log_append_mail_message(ctx, mail, MAIL_LOG_EVENT_DELETE,
                         "delete");
    } else {
        mail_log_append_mail_message(ctx, mail, MAIL_LOG_EVENT_UNDELETE,
                         "undelete");
    }
}

static void
mail_log_mail_update_keywords(void *txn, struct mail *mail,
                  const char *const *old_keywords ATTR_UNUSED)
{
    struct mail_log_mail_txn_context *ctx =
        (struct mail_log_mail_txn_context *)txn;

    mail_log_append_mail_message(ctx, mail, MAIL_LOG_EVENT_FLAG_CHANGE,
                     "flag_change");
}

static void mail_log_save(const struct mail_log_message *msg, uint32_t uid)
{
    if (msg->ignore) {
        /* not logging this save/copy */
    } else if (msg->pretext == NULL)
        i_info("%s", msg->text);
    else if (uid != 0)
        i_info("%s%u%s", msg->pretext, uid, msg->text);
    else
        i_info("%serror%s", msg->pretext, msg->text);
}

static void
mail_log_mail_transaction_commit(void *txn,
                 struct mail_transaction_commit_changes *changes)
{
    struct mail_log_mail_txn_context *ctx =
        (struct mail_log_mail_txn_context *)txn;
    struct mail_log_message *msg;
    struct seq_range_iter iter;
    unsigned int n = 0;
    uint32_t uid;

    seq_range_array_iter_init(&iter, &changes->saved_uids);
    for (msg = ctx->messages; msg != NULL; msg = msg->next) {
        if (msg->event == MAIL_LOG_EVENT_SAVE ||
            msg->event == MAIL_LOG_EVENT_COPY) {
            if (!seq_range_array_iter_nth(&iter, n++, &uid))
                uid = 0;
            mail_log_save(msg, uid);
        } else {
            i_assert(msg->pretext == NULL);
            i_info("%s", msg->text);
        }
    }
    i_assert(!seq_range_array_iter_nth(&iter, n, &uid));

    pool_unref(&ctx->pool);
}

static void mail_log_mail_transaction_rollback(void *txn)
{
    struct mail_log_mail_txn_context *ctx =
        (struct mail_log_mail_txn_context *)txn;

    pool_unref(&ctx->pool);
}

static void
mail_log_mailbox_create(struct mailbox *box)
{
    struct mail_log_user *muser = MAIL_LOG_USER_CONTEXT(box->storage->user);

    if ((muser->events & MAIL_LOG_EVENT_MAILBOX_CREATE) == 0)
        return;

    i_info("Mailbox created: %s",
           str_sanitize(mailbox_get_vname(box), MAILBOX_NAME_LOG_LEN));
}

static void
mail_log_mailbox_delete_commit(void *txn ATTR_UNUSED, struct mailbox *box)
{
    struct mail_log_user *muser = MAIL_LOG_USER_CONTEXT(box->storage->user);

    if ((muser->events & MAIL_LOG_EVENT_MAILBOX_DELETE) == 0)
        return;

    i_info("Mailbox deleted: %s",
           str_sanitize(mailbox_get_vname(box), MAILBOX_NAME_LOG_LEN));
}

static void
mail_log_mailbox_rename(struct mailbox *src, struct mailbox *dest)
{
    struct mail_log_user *muser = MAIL_LOG_USER_CONTEXT(src->storage->user);

    if ((muser->events & MAIL_LOG_EVENT_MAILBOX_RENAME) == 0)
        return;

    i_info("Mailbox renamed: %s -> %s",
           str_sanitize(mailbox_get_vname(src), MAILBOX_NAME_LOG_LEN),
           str_sanitize(mailbox_get_vname(dest), MAILBOX_NAME_LOG_LEN));
}

static const struct notify_vfuncs mail_log_vfuncs = {
    .mail_transaction_begin = mail_log_mail_transaction_begin,
    .mail_save = mail_log_mail_save,
    .mail_copy = mail_log_mail_copy,
    .mail_expunge = mail_log_mail_expunge,
    .mail_update_flags = mail_log_mail_update_flags,
    .mail_update_keywords = mail_log_mail_update_keywords,
    .mail_transaction_commit = mail_log_mail_transaction_commit,
    .mail_transaction_rollback = mail_log_mail_transaction_rollback,
    .mailbox_create = mail_log_mailbox_create,
    .mailbox_delete_commit = mail_log_mailbox_delete_commit,
    .mailbox_rename = mail_log_mailbox_rename
};

static struct notify_context *mail_log_ctx;

static struct mail_storage_hooks mail_log_mail_storage_hooks = {
    .mail_user_created = mail_log_mail_user_created
};

void mail_log_plugin_init(struct module *module)
{
    mail_log_ctx = notify_register(&mail_log_vfuncs);
    mail_storage_hooks_add(module, &mail_log_mail_storage_hooks);
}

void mail_log_plugin_deinit(void)
{
    mail_storage_hooks_remove(&mail_log_mail_storage_hooks);
    notify_unregister(mail_log_ctx);
}

const char *mail_log_plugin_dependencies[] = { "notify", NULL };