diff options
Diffstat (limited to 'logwrapper/logwrap.cpp')
-rw-r--r-- | logwrapper/logwrap.cpp | 615 |
1 files changed, 615 insertions, 0 deletions
diff --git a/logwrapper/logwrap.cpp b/logwrapper/logwrap.cpp new file mode 100644 index 000000000..5a518bc56 --- /dev/null +++ b/logwrapper/logwrap.cpp @@ -0,0 +1,615 @@ +/* + * 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->log_target & LOG_FILE) { + 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_target & LOG_FILE) { + fclose(log_info.fp); /* Also closes underlying fd */ + } + 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; +} |