cyrus-imapd-3.0.16/imap/sync_log.c

/* sync_log.c -- Cyrus synchonization logging functions
 *
 * Copyright (c) 1994-2008 Carnegie Mellon University.  All rights reserved.
 *
 * Redistribution and use in source and binary forms, with or without
 * modification, are permitted provided that the following conditions
 * are met:
 *
 * 1. Redistributions of source code must retain the above copyright
 *    notice, this list of conditions and the following disclaimer.
 *
 * 2. Redistributions in binary form must reproduce the above copyright
 *    notice, this list of conditions and the following disclaimer in
 *    the documentation and/or other materials provided with the
 *    distribution.
 *
 * 3. The name "Carnegie Mellon University" must not be used to
 *    endorse or promote products derived from this software without
 *    prior written permission. For permission or any legal
 *    details, please contact
 *      Carnegie Mellon University
 *      Center for Technology Transfer and Enterprise Creation
 *      4615 Forbes Avenue
 *      Suite 302
 *      Pittsburgh, PA  15213
 *      (412) 268-7393, fax: (412) 268-7395
 *      innovation@andrew.cmu.edu
 *
 * 4. Redistributions of any form whatsoever must retain the following
 *    acknowledgment:
 *    "This product includes software developed by Computing Services
 *     at Carnegie Mellon University (http://www.cmu.edu/computing/)."
 *
 * CARNEGIE MELLON UNIVERSITY DISCLAIMS ALL WARRANTIES WITH REGARD TO
 * THIS SOFTWARE, INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
 * AND FITNESS, IN NO EVENT SHALL CARNEGIE MELLON UNIVERSITY BE LIABLE
 * FOR ANY SPECIAL, INDIRECT OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
 * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN
 * AN ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING
 * OUT OF OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
 *
 * Original version written by David Carter <dpc22@cam.ac.uk>
 * Rewritten and integrated into Cyrus by Ken Murchison <ken@oceana.com>
 */

/* YYY Need better quoting for obscure filenames: use literals? */

#include <config.h>

#ifdef HAVE_UNISTD_H
#include <unistd.h>
#endif
#include <stdarg.h>
#include <stdlib.h>
#include <stdio.h>
#include <string.h>
#include <syslog.h>
#include <errno.h>

#include "assert.h"
#include "exitcodes.h"
#include "sync_log.h"
#include "global.h"
#include "cyr_lock.h"
#include "mailbox.h"
#include "retry.h"
#include "util.h"
#include "xmalloc.h"
#include "xstrlcpy.h"

/* generated headers are not necessarily in current directory */
#include "imap/imap_err.h"

static int sync_log_suppressed = 0;
static strarray_t *channels = NULL;
static strarray_t *unsuppressable = NULL;

EXPORTED void sync_log_init(void)
{
    const char *conf;
    int i;


    /* sync_log_init() may be called more than once */
    if (channels) strarray_free(channels);

    conf = config_getstring(IMAPOPT_SYNC_LOG_CHANNELS);
    if (!conf) conf = "\"\"";
    channels = strarray_split(conf, " ", 0);
    /*
     * The sysadmin can specify "" in the value of sync_log_channels to
     * mean the default channel name - this will be useful for sysadmins
     * who want to start using a sync log channel for squatter but who
     * have been using the default sync log channel for sync_client.
     */
    i = strarray_find(channels, "\"\"", 0);
    if (i >= 0)
        strarray_set(channels, i, NULL);

    strarray_free(unsuppressable);
    unsuppressable = NULL;
    conf = config_getstring(IMAPOPT_SYNC_LOG_UNSUPPRESSABLE_CHANNELS);
    if (conf)
        unsuppressable = strarray_split(conf, " ", 0);
}

EXPORTED void sync_log_suppress(void)
{
    sync_log_suppressed = 1;
}

EXPORTED void sync_log_done(void)
{
    strarray_free(channels);
    channels = NULL;

    strarray_free(unsuppressable);
    unsuppressable = NULL;
}

static char *sync_log_fname(const char *channel)
{
    static char buf[MAX_MAILBOX_PATH];

    if (channel)
        snprintf(buf, MAX_MAILBOX_PATH,
                 "%s/sync/%s/log", config_dir, channel);
    else
        snprintf(buf, MAX_MAILBOX_PATH,
                 "%s/sync/log", config_dir);

    return buf;
}

static int sync_log_enabled(const char *channel)
{
    if (!config_getswitch(IMAPOPT_SYNC_LOG))
        return 0;       /* entire mechanism is disabled */
    if (!sync_log_suppressed)
        return 1;       /* _suppress() wasn't called */
    if (unsuppressable && strarray_find(unsuppressable, channel, 0) >= 0)
        return 1;       /* channel is unsuppressable */
    return 0;           /* suppressed */
}

static void sync_log_base(const char *channel, const char *string)
{
    int fd;
    struct stat sbuffile, sbuffd;
    int retries = 0;
    const char *fname;

    fname = sync_log_fname(channel);

    while (retries++ < SYNC_LOG_RETRIES) {
        fd = open(fname, O_WRONLY|O_APPEND|O_CREAT, 0640);
        if (fd < 0 && errno == ENOENT) {
            if (!cyrus_mkdir(fname, 0755)) {
                fd = open(fname, O_WRONLY|O_APPEND|O_CREAT, 0640);
            }
        }
        if (fd < 0) {
            syslog(LOG_ERR, "sync_log(): Unable to write to log file %s: %s",
                   fname, strerror(errno));
            return;
        }

        if (lock_blocking(fd, fname) == -1) {
            syslog(LOG_ERR, "sync_log(): Failed to lock %s for %s: %m",
                   fname, string);
            xclose(fd);
            return;
        }

        /* Check that the file wasn't renamed after it was opened above */
        if ((fstat(fd, &sbuffd) == 0) &&
            (stat(fname, &sbuffile) == 0) &&
            (sbuffd.st_ino == sbuffile.st_ino))
            break;

        lock_unlock(fd, fname);
        xclose(fd);
    }
    if (retries >= SYNC_LOG_RETRIES) {
        xclose(fd);
        syslog(LOG_ERR,
               "sync_log(): Failed to lock %s for %s after %d attempts",
               fname, string, retries);
        return;
    }

    if (retry_write(fd, string, strlen(string)) < 0)
        syslog(LOG_ERR, "write() to %s failed: %s",
               fname, strerror(errno));

    (void)fsync(fd); /* paranoia */
    lock_unlock(fd, fname);
    xclose(fd);
}

static const char *sync_quote_name(const char *name)
{
    static char buf[MAX_MAILBOX_BUFFER+3]; /* "x2 plus \0 */
    char c;
    int src;
    int dst = 0;
    int need_quote = 0;

    /* initial quote */
    buf[dst++] = '"';

    /* degenerate case - no name is the empty string, quote it */
    if (!name || !*name) {
        need_quote = 1;
        goto end;
    }

    for (src = 0; name[src]; src++) {
        c = name[src];
        if ((c == '\r') || (c == '\n'))
            fatal("Illegal line break in folder name", EC_IOERR);

        /* quoteable characters */
        if ((c == '\\') || (c == '\"') || (c == '{') || (c == '}')) {
            need_quote = 1;
            buf[dst++] = '\\';
        }

        /* non-atom characters */
        else if ((c == ' ') || (c == '\t') || (c == '(') || (c == ')')) {
            need_quote = 1;
        }

        buf[dst++] = c;

        if (dst > MAX_MAILBOX_BUFFER)
            fatal("word too long", EC_IOERR);
    }

end:
    if (need_quote) {
        buf[dst++] = '\"';
        buf[dst] = '\0';
        return buf;
    }
    else {
        buf[dst] = '\0';
        return buf + 1; /* skip initial quote */
    }
}

#define BUFSIZE 4096

static char *va_format(const char *fmt, va_list ap)
{
    static char buf[BUFSIZE+1];
    size_t len;
    int ival;
    const char *sval;
    const char *p;

    for (len = 0, p = fmt; *p && len < BUFSIZE; p++) {
        if (*p != '%') {
            buf[len++] = *p;
            continue;
        }
        switch (*++p) {
        case 'd':
            ival = va_arg(ap, int);
            len += snprintf(buf+len, BUFSIZE-len, "%d", ival);
            break;
        case 's':
            sval = va_arg(ap, const char *);
            sval = sync_quote_name(sval);
            strlcpy(buf+len, sval, BUFSIZE-len);
            len += strlen(sval);
            break;
        default:
            buf[len++] = *p;
            break;
        }
    }

    if (buf[len-1] != '\n') buf[len++] = '\n';
    buf[len] = '\0';

    return buf;
}

EXPORTED void sync_log(const char *fmt, ...)
{
    va_list ap;
    const char *val;
    int i;

    if (!channels) return;

    va_start(ap, fmt);
    val = va_format(fmt, ap);
    va_end(ap);

    for (i = 0 ; i < channels->count ; i++) {
        const char *channel = channels->data[i];
        if (sync_log_enabled(channel))
            sync_log_base(channel, val);
    }
}

EXPORTED void sync_log_channel(const char *channel, const char *fmt, ...)
{
    va_list ap;
    const char *val;

    va_start(ap, fmt);
    val = va_format(fmt, ap);
    va_end(ap);

    sync_log_base(channel, val);
}

/*
 * Read-side sync log code
 */
struct sync_log_reader
{
    /*
     * This object works in three modes:
     *
     * - initialised with a sync log channel
     *      - standard mode used by sync_client
     *      - slr->log_file != NULL
     *      - slr->work_file is the name of a rename()d
     *        file that needs to be unlink()ed.
     *
     * - initialised with a saved file name
     *      - used by the sync_client -f option
     *      - slr->log_file = NULL
     *      - slr->work_file is the file given us by the user
     *        which it's important that we do not unlink()
     *
     * - initialised with a file descriptor
     *      - slr->log_file = NULL
     *      - slr->work_file = NULL
     *      - slr->fd is a file descriptor, probably stdin,
     *        and possibly a pipe
     *      - we cannot unlink() anything even if we wanted to.
     */
    char *log_file;
    char *work_file;
    int fd;
    int fd_is_ours;
    struct protstream *input;
    struct buf type;
    struct buf arg1;
    struct buf arg2;
};

static sync_log_reader_t *sync_log_reader_alloc(void)
{
    sync_log_reader_t *slr = xzmalloc(sizeof(sync_log_reader_t));
    slr->fd = -1;
    return slr;
}

/*
 * Create a sync log reader object which will read from the given sync log
 * channel 'channel'.  The channel may be NULL for the default channel.
 * Returns a new object which must be freed with sync_log_reader_free().
 * Does not return NULL.
 */
EXPORTED sync_log_reader_t *sync_log_reader_create_with_channel(const char *channel)
{
    sync_log_reader_t *slr = sync_log_reader_alloc();
    struct buf buf = BUF_INITIALIZER;

    slr->log_file = xstrdup(sync_log_fname(channel));

    /* Create a work log filename.  We will process this
     * first if it exists */
    buf_printf(&buf, "%s-run", slr->log_file);
    slr->work_file = buf_release(&buf);

    return slr;
}

/*
 * Create a sync log reader object which will read from the given file
 * 'filename'.  Returns a new object which must be freed with
 * sync_log_reader_free().  Does not return NULL.
 */
EXPORTED sync_log_reader_t *sync_log_reader_create_with_filename(const char *filename)
{
    sync_log_reader_t *slr = sync_log_reader_alloc();
    slr->work_file = xstrdup(filename);
    /* slr->log_file remain NULL, which matters later */
    return slr;
}

/*
 * Create a sync log reader object which will read from the given file
 * descriptor 'fd'.  The file descriptor must be open for reading and
 * is not closed.  Returns a new object which must be freed with
 * sync_log_reader_free().  Does not return NULL.
 */
EXPORTED sync_log_reader_t *sync_log_reader_create_with_fd(int fd)
{
    sync_log_reader_t *slr = sync_log_reader_alloc();
    slr->fd = fd;
    slr->fd_is_ours = 0;
    /* slr->log_file remain NULL, which matters later */
    return slr;
}

/*
 * Free a sync log reader object.
 */
EXPORTED void sync_log_reader_free(sync_log_reader_t *slr)
{
    if (!slr) return;
    if (slr->input) prot_free(slr->input);
    if (slr->fd_is_ours && slr->fd >= 0) close(slr->fd);
    free(slr->log_file);
    free(slr->work_file);
    buf_free(&slr->type);
    buf_free(&slr->arg1);
    buf_free(&slr->arg2);
    free(slr);
}

/*
 * Begin reading a sync log file.  If the reader is reading from a
 * channel, rename the current log file so it will not be appended to by
 * the write side code, and open the file. Otherwise, just open the file
 * (note this is still necessary even when the reader is reading from a
 * file descriptor).
 *
 * When sync_log_reader_begin() returns success, you should loop calling
 * sync_log_reader_getitem() and handling the items, until it returns
 * EOF, and then call sync_log_reader_end().
 *
 * Returns zero on success, IMAP_AGAIN if reading from a channel and
 * there is no current log file, or an IMAP error code on failure.
 */
EXPORTED int sync_log_reader_begin(sync_log_reader_t *slr)
{
    struct stat sbuf;
    int r;

    if (slr->input) {
        r = sync_log_reader_end(slr);
        if (r) return r;
    }

    if (stat(slr->work_file, &sbuf) == 0) {
        /* Existing work log file - process this first */
        syslog(LOG_NOTICE,
               "Reprocessing sync log file %s", slr->work_file);
    }
    else if (!slr->log_file) {
        syslog(LOG_ERR, "Failed to stat %s: %m",
               slr->log_file);
        return IMAP_IOERROR;
    }
    else {
        /* Check for sync_log file */
        if (stat(slr->log_file, &sbuf) < 0) {
            if (errno == ENOENT)
                return IMAP_AGAIN;  /* no problem, try again later */
            syslog(LOG_ERR, "Failed to stat %s: %m",
                   slr->log_file);
            return IMAP_IOERROR;
        }

        /* Move sync_log to our work file */
        if (rename(slr->log_file, slr->work_file) < 0) {
            syslog(LOG_ERR, "Rename %s -> %s failed: %m",
                   slr->log_file, slr->work_file);
            return IMAP_IOERROR;
        }
    }

    if (slr->fd < 0) {
        int fd = open(slr->work_file, O_RDWR, 0);
        if (fd < 0) {
            syslog(LOG_ERR, "Failed to open %s: %m", slr->work_file);
            return IMAP_IOERROR;
        }

        if (lock_blocking(fd, slr->work_file) < 0) {
            syslog(LOG_ERR, "Failed to lock %s: %m", slr->work_file);
            close(fd);
            return IMAP_IOERROR;
        }

        slr->fd = fd;
        slr->fd_is_ours = 1;

        /* we can unlock immediately, since we have serialised
         * any process which held the lock over the rename.  All
         * future attempts to lock this inode will stat and notice
         * the rename, so they won't write any more */
        lock_unlock(slr->fd, slr->work_file);
    }

    slr->input = prot_new(slr->fd, /*write*/0);

    return 0;
}

EXPORTED const char *sync_log_reader_get_file_name(const sync_log_reader_t *slr)
{
    return slr->work_file;
}

/*
 * Finish reading a sync log file.  Closes the file (and, if the reader
 * is reading from a channel, unlinks the work file and prepares for the
 * next file).  Returns 0 on success or an IMAP error code on failure.
 */
EXPORTED int sync_log_reader_end(sync_log_reader_t *slr)
{
    if (!slr->input)
        return 0;

    if (slr->input) {
        prot_free(slr->input);
        slr->input = NULL;
    }

    if (slr->fd_is_ours && slr->fd >= 0) {
        lock_unlock(slr->fd, slr->work_file);
        close(slr->fd);
        slr->fd = -1;
    }

    if (slr->log_file) {
        /* We were initialised with a sync log channel, whose
         * log file we rename()d to the work file.  Now that
         * we've done with the work file we can unlink it.
         * Further checks at this point are just paranoia. */
        if (slr->work_file && unlink(slr->work_file) < 0) {
            syslog(LOG_ERR, "Unlink %s failed: %m", slr->work_file);
            return IMAP_IOERROR;
        }
    }

    return 0;
}

/*
 * Read a single log item from a sync log file.  The item will be
 * returned as three constant strings.  The first string is the type of
 * the item (e.g. "MAILBOX") and is always capitalised.  The second and
 * third strings are arguments.
 *
 * Returns 0 on success, EOF when the end of the file is reached, or an
 * IMAP error code on failure.
 */
EXPORTED int sync_log_reader_getitem(sync_log_reader_t *slr,
                                     const char *args[3])
{
    int c;
    const char *arg1s = NULL;
    const char *arg2s = NULL;

    if (!slr->input)
        return EOF;

    for (;;) {
        if ((c = getword(slr->input, &slr->type)) == EOF)
            return EOF;

        /* Ignore blank lines */
        if (c == '\r') c = prot_getc(slr->input);
        if (c == '\n')
            continue;

        if (c != ' ') {
            syslog(LOG_ERR, "Invalid input");
            eatline(slr->input, c);
            continue;
        }

        if ((c = getastring(slr->input, 0, &slr->arg1)) == EOF) return EOF;
        arg1s = slr->arg1.s;

        arg2s = NULL;
        if (c == ' ') {
            if ((c = getastring(slr->input, 0, &slr->arg2)) == EOF) return EOF;
            arg2s = slr->arg2.s;
        }

        if (c == '\r') c = prot_getc(slr->input);
        if (c != '\n') {
            syslog(LOG_ERR, "Garbage at end of input line");
            eatline(slr->input, c);
            continue;
        }

        break;
    }

    ucase(slr->type.s);
    args[0] = slr->type.s;
    args[1] = arg1s;
    args[2] = arg2s;
    return 0;
}