/* * 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 #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include 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(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(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(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; }