logging/logwrapper/logwrap.cpp

/*
 * Copyright (C) 2008 The Android Open Source Project
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *      http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */

#include <errno.h>
#include <fcntl.h>
#include <libgen.h>
#include <poll.h>
#include <pthread.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/socket.h>
#include <sys/types.h>
#include <sys/wait.h>
#include <unistd.h>

#include <algorithm>

#include <android-base/macros.h>
#include <cutils/klog.h>
#include <log/log.h>
#include <logwrap/logwrap.h>

static pthread_mutex_t fd_mutex = PTHREAD_MUTEX_INITIALIZER;
// Protected by fd_mutex.  These signals must be blocked while modifying as well.
static pid_t child_pid;
static struct sigaction old_int;
static struct sigaction old_quit;
static struct sigaction old_hup;

#define ERROR(fmt, args...)                         \
    do {                                            \
        fprintf(stderr, fmt, ##args);               \
        ALOG(LOG_ERROR, "logwrapper", fmt, ##args); \
    } while (0)

#define FATAL_CHILD(fmt, args...) \
    do {                          \
        ERROR(fmt, ##args);       \
        _exit(-1);                \
    } while (0)

#define MAX_KLOG_TAG 16

/* This is a simple buffer that holds up to the first beginning_buf->buf_size
 * bytes of output from a command.
 */
#define BEGINNING_BUF_SIZE 0x1000
struct beginning_buf {
    char* buf;
    size_t alloc_len;
    /* buf_size is the usable space, which is one less than the allocated size */
    size_t buf_size;
    size_t used_len;
};

/* This is a circular buf that holds up to the last ending_buf->buf_size bytes
 * of output from a command after the first beginning_buf->buf_size bytes
 * (which are held in beginning_buf above).
 */
#define ENDING_BUF_SIZE 0x1000
struct ending_buf {
    char* buf;
    ssize_t alloc_len;
    /* buf_size is the usable space, which is one less than the allocated size */
    ssize_t buf_size;
    ssize_t used_len;
    /* read and write offsets into the circular buffer */
    int read;
    int write;
};

/* A structure to hold all the abbreviated buf data */
struct abbr_buf {
    struct beginning_buf b_buf;
    struct ending_buf e_buf;
    int beginning_buf_full;
};

/* Collect all the various bits of info needed for logging in one place. */
struct log_info {
    int log_target;
    char klog_fmt[MAX_KLOG_TAG * 2];
    const char* btag;
    bool abbreviated;
    FILE* fp;
    struct abbr_buf a_buf;
};

/* Forware declaration */
static void add_line_to_abbr_buf(struct abbr_buf* a_buf, char* linebuf, int linelen);

/* Return 0 on success, and 1 when full */
static int add_line_to_linear_buf(struct beginning_buf* b_buf, char* line, ssize_t line_len) {
    int full = 0;

    if ((line_len + b_buf->used_len) > b_buf->buf_size) {
        full = 1;
    } else {
        /* Add to the end of the buf */
        memcpy(b_buf->buf + b_buf->used_len, line, line_len);
        b_buf->used_len += line_len;
    }

    return full;
}

static void add_line_to_circular_buf(struct ending_buf* e_buf, char* line, ssize_t line_len) {
    ssize_t free_len;
    ssize_t needed_space;
    int cnt;

    if (e_buf->buf == nullptr) {
        return;
    }

    if (line_len > e_buf->buf_size) {
        return;
    }

    free_len = e_buf->buf_size - e_buf->used_len;

    if (line_len > free_len) {
        /* remove oldest entries at read, and move read to make
         * room for the new string */
        needed_space = line_len - free_len;
        e_buf->read = (e_buf->read + needed_space) % e_buf->buf_size;
        e_buf->used_len -= needed_space;
    }

    /* Copy the line into the circular buffer, dealing with possible
     * wraparound.
     */
    cnt = std::min(line_len, e_buf->buf_size - e_buf->write);
    memcpy(e_buf->buf + e_buf->write, line, cnt);
    if (cnt < line_len) {
        memcpy(e_buf->buf, line + cnt, line_len - cnt);
    }
    e_buf->used_len += line_len;
    e_buf->write = (e_buf->write + line_len) % e_buf->buf_size;
}

/* Log directly to the specified log */
static void do_log_line(struct log_info* log_info, const char* line) {
    if (log_info->log_target & LOG_KLOG) {
        klog_write(6, log_info->klog_fmt, line);
    }
    if (log_info->log_target & LOG_ALOG) {
        ALOG(LOG_INFO, log_info->btag, "%s", line);
    }
    if (log_info->fp) {
        fprintf(log_info->fp, "%s\n", line);
    }
}

/* Log to either the abbreviated buf, or directly to the specified log
 * via do_log_line() above.
 */
static void log_line(struct log_info* log_info, char* line, int len) {
    if (log_info->abbreviated) {
        add_line_to_abbr_buf(&log_info->a_buf, line, len);
    } else {
        do_log_line(log_info, line);
    }
}

/*
 * The kernel will take a maximum of 1024 bytes in any single write to
 * the kernel logging device file, so find and print each line one at
 * a time.  The allocated size for buf should be at least 1 byte larger
 * than buf_size (the usable size of the buffer) to make sure there is
 * room to temporarily stuff a null byte to terminate a line for logging.
 */
static void print_buf_lines(struct log_info* log_info, char* buf, int buf_size) {
    char* line_start;
    char c;
    int i;

    line_start = buf;
    for (i = 0; i < buf_size; i++) {
        if (*(buf + i) == '\n') {
            /* Found a line ending, print the line and compute new line_start */
            /* Save the next char and replace with \0 */
            c = *(buf + i + 1);
            *(buf + i + 1) = '\0';
            do_log_line(log_info, line_start);
            /* Restore the saved char */
            *(buf + i + 1) = c;
            line_start = buf + i + 1;
        } else if (*(buf + i) == '\0') {
            /* The end of the buffer, print the last bit */
            do_log_line(log_info, line_start);
            break;
        }
    }
    /* If the buffer was completely full, and didn't end with a newline, just
     * ignore the partial last line.
     */
}

static void init_abbr_buf(struct abbr_buf* a_buf) {
    char* new_buf;

    memset(a_buf, 0, sizeof(struct abbr_buf));
    new_buf = static_cast<char*>(malloc(BEGINNING_BUF_SIZE));
    if (new_buf) {
        a_buf->b_buf.buf = new_buf;
        a_buf->b_buf.alloc_len = BEGINNING_BUF_SIZE;
        a_buf->b_buf.buf_size = BEGINNING_BUF_SIZE - 1;
    }
    new_buf = static_cast<char*>(malloc(ENDING_BUF_SIZE));
    if (new_buf) {
        a_buf->e_buf.buf = new_buf;
        a_buf->e_buf.alloc_len = ENDING_BUF_SIZE;
        a_buf->e_buf.buf_size = ENDING_BUF_SIZE - 1;
    }
}

static void free_abbr_buf(struct abbr_buf* a_buf) {
    free(a_buf->b_buf.buf);
    free(a_buf->e_buf.buf);
}

static void add_line_to_abbr_buf(struct abbr_buf* a_buf, char* linebuf, int linelen) {
    if (!a_buf->beginning_buf_full) {
        a_buf->beginning_buf_full = add_line_to_linear_buf(&a_buf->b_buf, linebuf, linelen);
    }
    if (a_buf->beginning_buf_full) {
        add_line_to_circular_buf(&a_buf->e_buf, linebuf, linelen);
    }
}

static void print_abbr_buf(struct log_info* log_info) {
    struct abbr_buf* a_buf = &log_info->a_buf;

    /* Add the abbreviated output to the kernel log */
    if (a_buf->b_buf.alloc_len) {
        print_buf_lines(log_info, a_buf->b_buf.buf, a_buf->b_buf.used_len);
    }

    /* Print an ellipsis to indicate that the buffer has wrapped or
     * is full, and some data was not logged.
     */
    if (a_buf->e_buf.used_len == a_buf->e_buf.buf_size) {
        do_log_line(log_info, "...\n");
    }

    if (a_buf->e_buf.used_len == 0) {
        return;
    }

    /* Simplest way to print the circular buffer is allocate a second buf
     * of the same size, and memcpy it so it's a simple linear buffer,
     * and then cal print_buf_lines on it */
    if (a_buf->e_buf.read < a_buf->e_buf.write) {
        /* no wrap around, just print it */
        print_buf_lines(log_info, a_buf->e_buf.buf + a_buf->e_buf.read, a_buf->e_buf.used_len);
    } else {
        /* The circular buffer will always have at least 1 byte unused,
         * so by allocating alloc_len here we will have at least
         * 1 byte of space available as required by print_buf_lines().
         */
        char* nbuf = static_cast<char*>(malloc(a_buf->e_buf.alloc_len));
        if (!nbuf) {
            return;
        }
        int first_chunk_len = a_buf->e_buf.buf_size - a_buf->e_buf.read;
        memcpy(nbuf, a_buf->e_buf.buf + a_buf->e_buf.read, first_chunk_len);
        /* copy second chunk */
        memcpy(nbuf + first_chunk_len, a_buf->e_buf.buf, a_buf->e_buf.write);
        print_buf_lines(log_info, nbuf, first_chunk_len + a_buf->e_buf.write);
        free(nbuf);
    }
}

static void signal_handler(int signal_num);

static void block_signals(sigset_t* oldset) {
    sigset_t blockset;

    sigemptyset(&blockset);
    sigaddset(&blockset, SIGINT);
    sigaddset(&blockset, SIGQUIT);
    sigaddset(&blockset, SIGHUP);
    pthread_sigmask(SIG_BLOCK, &blockset, oldset);
}

static void unblock_signals(sigset_t* oldset) {
    pthread_sigmask(SIG_SETMASK, oldset, nullptr);
}

static void setup_signal_handlers(pid_t pid) {
    struct sigaction handler = {.sa_handler = signal_handler};

    child_pid = pid;
    sigaction(SIGINT, &handler, &old_int);
    sigaction(SIGQUIT, &handler, &old_quit);
    sigaction(SIGHUP, &handler, &old_hup);
}

static void restore_signal_handlers() {
    sigaction(SIGINT, &old_int, nullptr);
    sigaction(SIGQUIT, &old_quit, nullptr);
    sigaction(SIGHUP, &old_hup, nullptr);
    child_pid = 0;
}

static void signal_handler(int signal_num) {
    if (child_pid == 0 || kill(child_pid, signal_num) != 0) {
        restore_signal_handlers();
        raise(signal_num);
    }
}

static int parent(const char* tag, int parent_read, pid_t pid, int* chld_sts, int log_target,
                  bool abbreviated, const char* file_path, bool forward_signals) {
    int status = 0;
    char buffer[4096];
    struct pollfd poll_fds[] = {
            {
                    .fd = parent_read,
                    .events = POLLIN,
            },
    };
    int rc = 0;
    int fd;

    struct log_info log_info = {};

    int a = 0;  // start index of unprocessed data
    int b = 0;  // end index of unprocessed data
    int sz;
    bool found_child = false;
    // There is a very small chance that opening child_ptty in the child will fail, but in this case
    // POLLHUP will not be generated below.  Therefore, we use a 1 second timeout for poll() until
    // we receive a message from child_ptty.  If this times out, we call waitpid() with WNOHANG to
    // check the status of the child process and exit appropriately if it has terminated.
    bool received_messages = false;
    char tmpbuf[256];

    log_info.btag = basename(tag);
    if (!log_info.btag) {
        log_info.btag = tag;
    }

    if (abbreviated && (log_target == LOG_NONE)) {
        abbreviated = 0;
    }
    if (abbreviated) {
        init_abbr_buf(&log_info.a_buf);
    }

    if (log_target & LOG_KLOG) {
        snprintf(log_info.klog_fmt, sizeof(log_info.klog_fmt), "<6>%.*s: %%s\n", MAX_KLOG_TAG,
                 log_info.btag);
    }

    if ((log_target & LOG_FILE) && !file_path) {
        /* No file_path specified, clear the LOG_FILE bit */
        log_target &= ~LOG_FILE;
    }

    if (log_target & LOG_FILE) {
        fd = open(file_path, O_WRONLY | O_CREAT | O_CLOEXEC, 0664);
        if (fd < 0) {
            ERROR("Cannot log to file %s\n", file_path);
            log_target &= ~LOG_FILE;
        } else {
            lseek(fd, 0, SEEK_END);
            log_info.fp = fdopen(fd, "a");
        }
    }

    log_info.log_target = log_target;
    log_info.abbreviated = abbreviated;

    while (!found_child) {
        int timeout = received_messages ? -1 : 1000;
        if (TEMP_FAILURE_RETRY(poll(poll_fds, arraysize(poll_fds), timeout)) < 0) {
            ERROR("poll failed\n");
            rc = -1;
            goto err_poll;
        }

        if (poll_fds[0].revents & POLLIN) {
            received_messages = true;
            sz = TEMP_FAILURE_RETRY(read(parent_read, &buffer[b], sizeof(buffer) - 1 - b));

            sz += b;
            // Log one line at a time
            for (b = 0; b < sz; b++) {
                if (buffer[b] == '\r') {
                    if (abbreviated) {
                        /* The abbreviated logging code uses newline as
                         * the line separator.  Lucikly, the pty layer
                         * helpfully cooks the output of the command
                         * being run and inserts a CR before NL.  So
                         * I just change it to NL here when doing
                         * abbreviated logging.
                         */
                        buffer[b] = '\n';
                    } else {
                        buffer[b] = '\0';
                    }
                } else if (buffer[b] == '\n') {
                    buffer[b] = '\0';
                    log_line(&log_info, &buffer[a], b - a);
                    a = b + 1;
                }
            }

            if (a == 0 && b == sizeof(buffer) - 1) {
                // buffer is full, flush
                buffer[b] = '\0';
                log_line(&log_info, &buffer[a], b - a);
                b = 0;
            } else if (a != b) {
                // Keep left-overs
                b -= a;
                memmove(buffer, &buffer[a], b);
                a = 0;
            } else {
                a = 0;
                b = 0;
            }
        }

        if (!received_messages || (poll_fds[0].revents & POLLHUP)) {
            int ret;
            sigset_t oldset;

            if (forward_signals) {
                // Our signal handlers forward these signals to 'child_pid', but waitpid() may reap
                // the child, so we must block these signals until we either 1) conclude that the
                // child is still running or 2) determine the child has been reaped and we have
                // reset the signals to their original disposition.
                block_signals(&oldset);
            }

            int flags = (poll_fds[0].revents & POLLHUP) ? 0 : WNOHANG;
            ret = TEMP_FAILURE_RETRY(waitpid(pid, &status, flags));
            if (ret < 0) {
                rc = errno;
                ALOG(LOG_ERROR, "logwrap", "waitpid failed with %s\n", strerror(errno));
                goto err_waitpid;
            }
            if (ret > 0) {
                found_child = true;
            }

            if (forward_signals) {
                if (found_child) {
                    restore_signal_handlers();
                }
                unblock_signals(&oldset);
            }
        }
    }

    if (chld_sts != nullptr) {
        *chld_sts = status;
    } else {
        if (WIFEXITED(status))
            rc = WEXITSTATUS(status);
        else
            rc = -ECHILD;
    }

    // Flush remaining data
    if (a != b) {
        buffer[b] = '\0';
        log_line(&log_info, &buffer[a], b - a);
    }

    /* All the output has been processed, time to dump the abbreviated output */
    if (abbreviated) {
        print_abbr_buf(&log_info);
    }

    if (WIFEXITED(status)) {
        if (WEXITSTATUS(status)) {
            snprintf(tmpbuf, sizeof(tmpbuf), "%s terminated by exit(%d)\n", log_info.btag,
                     WEXITSTATUS(status));
            do_log_line(&log_info, tmpbuf);
        }
    } else {
        if (WIFSIGNALED(status)) {
            snprintf(tmpbuf, sizeof(tmpbuf), "%s terminated by signal %d\n", log_info.btag,
                     WTERMSIG(status));
            do_log_line(&log_info, tmpbuf);
        } else if (WIFSTOPPED(status)) {
            snprintf(tmpbuf, sizeof(tmpbuf), "%s stopped by signal %d\n", log_info.btag,
                     WSTOPSIG(status));
            do_log_line(&log_info, tmpbuf);
        }
    }

err_waitpid:
err_poll:
    if (log_info.fp) {
        fclose(log_info.fp);
    }
    if (abbreviated) {
        free_abbr_buf(&log_info.a_buf);
    }
    return rc;
}

static void child(int argc, const char* const* argv) {
    // create null terminated argv_child array
    char* argv_child[argc + 1];
    memcpy(argv_child, argv, argc * sizeof(char*));
    argv_child[argc] = nullptr;

    if (execvp(argv_child[0], argv_child)) {
        FATAL_CHILD("executing %s failed: %s\n", argv_child[0], strerror(errno));
    }
}

int logwrap_fork_execvp(int argc, const char* const* argv, int* status, bool forward_signals,
                        int log_target, bool abbreviated, const char* file_path) {
    pid_t pid;
    int parent_ptty;
    sigset_t oldset;
    int rc = 0;

    rc = pthread_mutex_lock(&fd_mutex);
    if (rc) {
        ERROR("failed to lock signal_fd mutex\n");
        goto err_lock;
    }

    /* Use ptty instead of socketpair so that STDOUT is not buffered */
    parent_ptty = TEMP_FAILURE_RETRY(posix_openpt(O_RDWR | O_CLOEXEC));
    if (parent_ptty < 0) {
        ERROR("Cannot create parent ptty\n");
        rc = -1;
        goto err_open;
    }

    char child_devname[64];
    if (grantpt(parent_ptty) || unlockpt(parent_ptty) ||
        ptsname_r(parent_ptty, child_devname, sizeof(child_devname)) != 0) {
        ERROR("Problem with /dev/ptmx\n");
        rc = -1;
        goto err_ptty;
    }

    if (forward_signals) {
        // Block these signals until we have the child pid and our signal handlers set up.
        block_signals(&oldset);
    }

    pid = fork();
    if (pid < 0) {
        ERROR("Failed to fork\n");
        rc = -1;
        goto err_fork;
    } else if (pid == 0) {
        pthread_mutex_unlock(&fd_mutex);
        if (forward_signals) {
            unblock_signals(&oldset);
        }

        setsid();

        int child_ptty = TEMP_FAILURE_RETRY(open(child_devname, O_RDWR | O_CLOEXEC));
        if (child_ptty < 0) {
            FATAL_CHILD("Cannot open child_ptty: %s\n", strerror(errno));
        }
        close(parent_ptty);

        dup2(child_ptty, 1);
        dup2(child_ptty, 2);
        close(child_ptty);

        child(argc, argv);
    } else {
        if (forward_signals) {
            setup_signal_handlers(pid);
            unblock_signals(&oldset);
        }

        rc = parent(argv[0], parent_ptty, pid, status, log_target, abbreviated, file_path,
                    forward_signals);

        if (forward_signals) {
            restore_signal_handlers();
        }
    }

err_fork:
    if (forward_signals) {
        unblock_signals(&oldset);
    }
err_ptty:
    close(parent_ptty);
err_open:
    pthread_mutex_unlock(&fd_mutex);
err_lock:
    return rc;
}