logwrapper/logwrap.c

   1 /*
   2  * Copyright (C) 2008 The Android Open Source Project
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at
   7  *
   8  *      http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16
  17 #include <string.h>
  18 #include <sys/types.h>
  19 #include <sys/socket.h>
  20 #include <poll.h>
  21 #include <sys/wait.h>
  22 #include <stdio.h>
  23 #include <stdlib.h>
  24 #include <unistd.h>
  25 #include <errno.h>
  26 #include <fcntl.h>
  27 #include <libgen.h>
  28 #include <stdbool.h>
  29 #include <pthread.h>
  30
  31 #include <logwrap/logwrap.h>
  32 #include "private/android_filesystem_config.h"
  33 #include "cutils/log.h"
  34 #include <cutils/klog.h>
  35
  36 #define ARRAY_SIZE(x)   (sizeof(x) / sizeof(*(x)))
  37 #define MIN(a,b) (((a)<(b))?(a):(b))
  38
  39 static pthread_mutex_t fd_mutex = PTHREAD_MUTEX_INITIALIZER;
  40
  41 #define ERROR(fmt, args...)                                                   \
  42 do {                                                                          \
  43     fprintf(stderr, fmt, ## args);                                            \
  44     ALOG(LOG_ERROR, "logwrapper", fmt, ## args);                              \
  45 } while(0)
  46
  47 #define FATAL_CHILD(fmt, args...)                                             \
  48 do {                                                                          \
  49     ERROR(fmt, ## args);                                                      \
  50     _exit(-1);                                                                \
  51 } while(0)
  52
  53 #define MAX_KLOG_TAG 16
  54
  55 /* This is a simple buffer that holds up to the first beginning_buf->buf_size
  56  * bytes of output from a command.
  57  */
  58 #define BEGINNING_BUF_SIZE 0x1000
  59 struct beginning_buf {
  60     char *buf;
  61     size_t alloc_len;
  62     /* buf_size is the usable space, which is one less than the allocated size */
  63     size_t buf_size;
  64     size_t used_len;
  65 };
  66
  67 /* This is a circular buf that holds up to the last ending_buf->buf_size bytes
  68  * of output from a command after the first beginning_buf->buf_size bytes
  69  * (which are held in beginning_buf above).
  70  */
  71 #define ENDING_BUF_SIZE 0x1000
  72 struct ending_buf {
  73     char *buf;
  74     ssize_t alloc_len;
  75     /* buf_size is the usable space, which is one less than the allocated size */
  76     ssize_t buf_size;
  77     ssize_t used_len;
  78     /* read and write offsets into the circular buffer */
  79     int read;
  80     int write;
  81 };
  82
  83  /* A structure to hold all the abbreviated buf data */
  84 struct abbr_buf {
  85     struct beginning_buf b_buf;
  86     struct ending_buf e_buf;
  87     int beginning_buf_full;
  88 };
  89
  90 /* Collect all the various bits of info needed for logging in one place. */
  91 struct log_info {
  92     int log_target;
  93     char klog_fmt[MAX_KLOG_TAG * 2];
  94     char *btag;
  95     bool abbreviated;
  96     FILE *fp;
  97     struct abbr_buf a_buf;
  98 };
  99
 100 /* Forware declaration */
 101 static void add_line_to_abbr_buf(struct abbr_buf *a_buf, char *linebuf, int linelen);
 102
 103 /* Return 0 on success, and 1 when full */
 104 static int add_line_to_linear_buf(struct beginning_buf *b_buf,
 105                                    char *line, ssize_t line_len)
 106 {
 107     size_t new_len;
 108     char *new_buf;
 109     int full = 0;
 110
 111     if ((line_len + b_buf->used_len) > b_buf->buf_size) {
 112         full = 1;
 113     } else {
 114         /* Add to the end of the buf */
 115         memcpy(b_buf->buf + b_buf->used_len, line, line_len);
 116         b_buf->used_len += line_len;
 117     }
 118
 119     return full;
 120 }
 121
 122 static void add_line_to_circular_buf(struct ending_buf *e_buf,
 123                                      char *line, ssize_t line_len)
 124 {
 125     ssize_t free_len;
 126     ssize_t needed_space;
 127     char *new_buf;
 128     int cnt;
 129
 130     if (e_buf->buf == NULL) {
 131         return;
 132     }
 133
 134    if (line_len > e_buf->buf_size) {
 135        return;
 136    }
 137
 138     free_len = e_buf->buf_size - e_buf->used_len;
 139
 140     if (line_len > free_len) {
 141         /* remove oldest entries at read, and move read to make
 142          * room for the new string */
 143         needed_space = line_len - free_len;
 144         e_buf->read = (e_buf->read + needed_space) % e_buf->buf_size;
 145         e_buf->used_len -= needed_space;
 146     }
 147
 148     /* Copy the line into the circular buffer, dealing with possible
 149      * wraparound.
 150      */
 151     cnt = MIN(line_len, e_buf->buf_size - e_buf->write);
 152     memcpy(e_buf->buf + e_buf->write, line, cnt);
 153     if (cnt < line_len) {
 154         memcpy(e_buf->buf, line + cnt, line_len - cnt);
 155     }
 156     e_buf->used_len += line_len;
 157     e_buf->write = (e_buf->write + line_len) % e_buf->buf_size;
 158 }
 159
 160 /* Log directly to the specified log */
 161 static void do_log_line(struct log_info *log_info, char *line) {
 162     if (log_info->log_target & LOG_KLOG) {
 163         klog_write(6, log_info->klog_fmt, line);
 164     }
 165     if (log_info->log_target & LOG_ALOG) {
 166         ALOG(LOG_INFO, log_info->btag, "%s", line);
 167     }
 168     if (log_info->log_target & LOG_FILE) {
 169         fprintf(log_info->fp, "%s\n", line);
 170     }
 171 }
 172
 173 /* Log to either the abbreviated buf, or directly to the specified log
 174  * via do_log_line() above.
 175  */
 176 static void log_line(struct log_info *log_info, char *line, int len) {
 177     if (log_info->abbreviated) {
 178         add_line_to_abbr_buf(&log_info->a_buf, line, len);
 179     } else {
 180         do_log_line(log_info, line);
 181     }
 182 }
 183
 184 /*
 185  * The kernel will take a maximum of 1024 bytes in any single write to
 186  * the kernel logging device file, so find and print each line one at
 187  * a time.  The allocated size for buf should be at least 1 byte larger
 188  * than buf_size (the usable size of the buffer) to make sure there is
 189  * room to temporarily stuff a null byte to terminate a line for logging.
 190  */
 191 static void print_buf_lines(struct log_info *log_info, char *buf, int buf_size)
 192 {
 193     char *line_start;
 194     char c;
 195     int line_len;
 196     int i;
 197
 198     line_start = buf;
 199     for (i = 0; i < buf_size; i++) {
 200         if (*(buf + i) == '\n') {
 201             /* Found a line ending, print the line and compute new line_start */
 202             /* Save the next char and replace with \0 */
 203             c = *(buf + i + 1);
 204             *(buf + i + 1) = '\0';
 205             do_log_line(log_info, line_start);
 206             /* Restore the saved char */
 207             *(buf + i + 1) = c;
 208             line_start = buf + i + 1;
 209         } else if (*(buf + i) == '\0') {
 210             /* The end of the buffer, print the last bit */
 211             do_log_line(log_info, line_start);
 212             break;
 213         }
 214     }
 215     /* If the buffer was completely full, and didn't end with a newline, just
 216      * ignore the partial last line.
 217      */
 218 }
 219
 220 static void init_abbr_buf(struct abbr_buf *a_buf) {
 221     char *new_buf;
 222
 223     memset(a_buf, 0, sizeof(struct abbr_buf));
 224     new_buf = malloc(BEGINNING_BUF_SIZE);
 225     if (new_buf) {
 226         a_buf->b_buf.buf = new_buf;
 227         a_buf->b_buf.alloc_len = BEGINNING_BUF_SIZE;
 228         a_buf->b_buf.buf_size = BEGINNING_BUF_SIZE - 1;
 229     }
 230     new_buf = malloc(ENDING_BUF_SIZE);
 231     if (new_buf) {
 232         a_buf->e_buf.buf = new_buf;
 233         a_buf->e_buf.alloc_len = ENDING_BUF_SIZE;
 234         a_buf->e_buf.buf_size = ENDING_BUF_SIZE - 1;
 235     }
 236 }
 237
 238 static void free_abbr_buf(struct abbr_buf *a_buf) {
 239     free(a_buf->b_buf.buf);
 240     free(a_buf->e_buf.buf);
 241 }
 242
 243 static void add_line_to_abbr_buf(struct abbr_buf *a_buf, char *linebuf, int linelen) {
 244     if (!a_buf->beginning_buf_full) {
 245         a_buf->beginning_buf_full =
 246             add_line_to_linear_buf(&a_buf->b_buf, linebuf, linelen);
 247     }
 248     if (a_buf->beginning_buf_full) {
 249         add_line_to_circular_buf(&a_buf->e_buf, linebuf, linelen);
 250     }
 251 }
 252
 253 static void print_abbr_buf(struct log_info *log_info) {
 254     struct abbr_buf *a_buf = &log_info->a_buf;
 255
 256     /* Add the abbreviated output to the kernel log */
 257     if (a_buf->b_buf.alloc_len) {
 258         print_buf_lines(log_info, a_buf->b_buf.buf, a_buf->b_buf.used_len);
 259     }
 260
 261     /* Print an ellipsis to indicate that the buffer has wrapped or
 262      * is full, and some data was not logged.
 263      */
 264     if (a_buf->e_buf.used_len == a_buf->e_buf.buf_size) {
 265         do_log_line(log_info, "...\n");
 266     }
 267
 268     if (a_buf->e_buf.used_len == 0) {
 269         return;
 270     }
 271
 272     /* Simplest way to print the circular buffer is allocate a second buf
 273      * of the same size, and memcpy it so it's a simple linear buffer,
 274      * and then cal print_buf_lines on it */
 275     if (a_buf->e_buf.read < a_buf->e_buf.write) {
 276         /* no wrap around, just print it */
 277         print_buf_lines(log_info, a_buf->e_buf.buf + a_buf->e_buf.read,
 278                         a_buf->e_buf.used_len);
 279     } else {
 280         /* The circular buffer will always have at least 1 byte unused,
 281          * so by allocating alloc_len here we will have at least
 282          * 1 byte of space available as required by print_buf_lines().
 283          */
 284         char * nbuf = malloc(a_buf->e_buf.alloc_len);
 285         if (!nbuf) {
 286             return;
 287         }
 288         int first_chunk_len = a_buf->e_buf.buf_size - a_buf->e_buf.read;
 289         memcpy(nbuf, a_buf->e_buf.buf + a_buf->e_buf.read, first_chunk_len);
 290         /* copy second chunk */
 291         memcpy(nbuf + first_chunk_len, a_buf->e_buf.buf, a_buf->e_buf.write);
 292         print_buf_lines(log_info, nbuf, first_chunk_len + a_buf->e_buf.write);
 293         free(nbuf);
 294     }
 295 }
 296
 297 static int parent(const char *tag, int parent_read, pid_t pid,
 298         int *chld_sts, int log_target, bool abbreviated, char *file_path) {
 299     int status = 0;
 300     char buffer[4096];
 301     struct pollfd poll_fds[] = {
 302         [0] = {
 303             .fd = parent_read,
 304             .events = POLLIN,
 305         },
 306     };
 307     int rc = 0;
 308     int fd;
 309
 310     struct log_info log_info;
 311
 312     int a = 0;  // start index of unprocessed data
 313     int b = 0;  // end index of unprocessed data
 314     int sz;
 315     bool found_child = false;
 316     char tmpbuf[256];
 317
 318     log_info.btag = basename(tag);
 319     if (!log_info.btag) {
 320         log_info.btag = (char*) tag;
 321     }
 322
 323     if (abbreviated && (log_target == LOG_NONE)) {
 324         abbreviated = 0;
 325     }
 326     if (abbreviated) {
 327         init_abbr_buf(&log_info.a_buf);
 328     }
 329
 330     if (log_target & LOG_KLOG) {
 331         snprintf(log_info.klog_fmt, sizeof(log_info.klog_fmt),
 332                  "<6>%.*s: %%s", MAX_KLOG_TAG, log_info.btag);
 333     }
 334
 335     if ((log_target & LOG_FILE) && !file_path) {
 336         /* No file_path specified, clear the LOG_FILE bit */
 337         log_target &= ~LOG_FILE;
 338     }
 339
 340     if (log_target & LOG_FILE) {
 341         fd = open(file_path, O_WRONLY | O_CREAT, 0664);
 342         if (fd < 0) {
 343             ERROR("Cannot log to file %s\n", file_path);
 344             log_target &= ~LOG_FILE;
 345         } else {
 346             lseek(fd, 0, SEEK_END);
 347             log_info.fp = fdopen(fd, "a");
 348         }
 349     }
 350
 351     log_info.log_target = log_target;
 352     log_info.abbreviated = abbreviated;
 353
 354     while (!found_child) {
 355         if (TEMP_FAILURE_RETRY(poll(poll_fds, ARRAY_SIZE(poll_fds), -1)) < 0) {
 356             ERROR("poll failed\n");
 357             rc = -1;
 358             goto err_poll;
 359         }
 360
 361         if (poll_fds[0].revents & POLLIN) {
 362             sz = read(parent_read, &buffer[b], sizeof(buffer) - 1 - b);
 363
 364             sz += b;
 365             // Log one line at a time
 366             for (b = 0; b < sz; b++) {
 367                 if (buffer[b] == '\r') {
 368                     if (abbreviated) {
 369                         /* The abbreviated logging code uses newline as
 370                          * the line separator.  Lucikly, the pty layer
 371                          * helpfully cooks the output of the command
 372                          * being run and inserts a CR before NL.  So
 373                          * I just change it to NL here when doing
 374                          * abbreviated logging.
 375                          */
 376                         buffer[b] = '\n';
 377                     } else {
 378                         buffer[b] = '\0';
 379                     }
 380                 } else if (buffer[b] == '\n') {
 381                     buffer[b] = '\0';
 382                     log_line(&log_info, &buffer[a], b - a);
 383                     a = b + 1;
 384                 }
 385             }
 386
 387             if (a == 0 && b == sizeof(buffer) - 1) {
 388                 // buffer is full, flush
 389                 buffer[b] = '\0';
 390                 log_line(&log_info, &buffer[a], b - a);
 391                 b = 0;
 392             } else if (a != b) {
 393                 // Keep left-overs
 394                 b -= a;
 395                 memmove(buffer, &buffer[a], b);
 396                 a = 0;
 397             } else {
 398                 a = 0;
 399                 b = 0;
 400             }
 401         }
 402
 403         if (poll_fds[0].revents & POLLHUP) {
 404             int ret;
 405
 406             ret = waitpid(pid, &status, WNOHANG);
 407             if (ret < 0) {
 408                 rc = errno;
 409                 ALOG(LOG_ERROR, "logwrap", "waitpid failed with %s\n", strerror(errno));
 410                 goto err_waitpid;
 411             }
 412             if (ret > 0) {
 413                 found_child = true;
 414             }
 415         }
 416     }
 417
 418     if (chld_sts != NULL) {
 419         *chld_sts = status;
 420     } else {
 421       if (WIFEXITED(status))
 422         rc = WEXITSTATUS(status);
 423       else
 424         rc = -ECHILD;
 425     }
 426
 427     // Flush remaining data
 428     if (a != b) {
 429       buffer[b] = '\0';
 430       log_line(&log_info, &buffer[a], b - a);
 431     }
 432
 433     /* All the output has been processed, time to dump the abbreviated output */
 434     if (abbreviated) {
 435         print_abbr_buf(&log_info);
 436     }
 437
 438     if (WIFEXITED(status)) {
 439       if (WEXITSTATUS(status)) {
 440         snprintf(tmpbuf, sizeof(tmpbuf),
 441                  "%s terminated by exit(%d)\n", log_info.btag, WEXITSTATUS(status));
 442         do_log_line(&log_info, tmpbuf);
 443       }
 444     } else {
 445       if (WIFSIGNALED(status)) {
 446         snprintf(tmpbuf, sizeof(tmpbuf),
 447                        "%s terminated by signal %d\n", log_info.btag, WTERMSIG(status));
 448         do_log_line(&log_info, tmpbuf);
 449       } else if (WIFSTOPPED(status)) {
 450         snprintf(tmpbuf, sizeof(tmpbuf),
 451                        "%s stopped by signal %d\n", log_info.btag, WSTOPSIG(status));
 452         do_log_line(&log_info, tmpbuf);
 453       }
 454     }
 455
 456 err_waitpid:
 457 err_poll:
 458     if (log_target & LOG_FILE) {
 459         fclose(log_info.fp); /* Also closes underlying fd */
 460     }
 461     if (abbreviated) {
 462         free_abbr_buf(&log_info.a_buf);
 463     }
 464     return rc;
 465 }
 466
 467 static void child(int argc, char* argv[]) {
 468     // create null terminated argv_child array
 469     char* argv_child[argc + 1];
 470     memcpy(argv_child, argv, argc * sizeof(char *));
 471     argv_child[argc] = NULL;
 472
 473     if (execvp(argv_child[0], argv_child)) {
 474         FATAL_CHILD("executing %s failed: %s\n", argv_child[0],
 475                 strerror(errno));
 476     }
 477 }
 478
 479 int android_fork_execvp_ext(int argc, char* argv[], int *status, bool ignore_int_quit,
 480         int log_target, bool abbreviated, char *file_path) {
 481     pid_t pid;
 482     int parent_ptty;
 483     int child_ptty;
 484     char *child_devname = NULL;
 485     struct sigaction intact;
 486     struct sigaction quitact;
 487     sigset_t blockset;
 488     sigset_t oldset;
 489     int rc = 0;
 490
 491     rc = pthread_mutex_lock(&fd_mutex);
 492     if (rc) {
 493         ERROR("failed to lock signal_fd mutex\n");
 494         goto err_lock;
 495     }
 496
 497     /* Use ptty instead of socketpair so that STDOUT is not buffered */
 498     parent_ptty = open("/dev/ptmx", O_RDWR);
 499     if (parent_ptty < 0) {
 500         ERROR("Cannot create parent ptty\n");
 501         rc = -1;
 502         goto err_open;
 503     }
 504
 505     if (grantpt(parent_ptty) || unlockpt(parent_ptty) ||
 506             ((child_devname = (char*)ptsname(parent_ptty)) == 0)) {
 507         ERROR("Problem with /dev/ptmx\n");
 508         rc = -1;
 509         goto err_ptty;
 510     }
 511
 512     child_ptty = open(child_devname, O_RDWR);
 513     if (child_ptty < 0) {
 514         ERROR("Cannot open child_ptty\n");
 515         rc = -1;
 516         goto err_child_ptty;
 517     }
 518
 519     sigemptyset(&blockset);
 520     sigaddset(&blockset, SIGINT);
 521     sigaddset(&blockset, SIGQUIT);
 522     pthread_sigmask(SIG_BLOCK, &blockset, &oldset);
 523
 524     pid = fork();
 525     if (pid < 0) {
 526         close(child_ptty);
 527         ERROR("Failed to fork\n");
 528         rc = -1;
 529         goto err_fork;
 530     } else if (pid == 0) {
 531         pthread_mutex_unlock(&fd_mutex);
 532         pthread_sigmask(SIG_SETMASK, &oldset, NULL);
 533         close(parent_ptty);
 534
 535         // redirect stdout and stderr
 536         dup2(child_ptty, 1);
 537         dup2(child_ptty, 2);
 538         close(child_ptty);
 539
 540         child(argc, argv);
 541     } else {
 542         close(child_ptty);
 543         if (ignore_int_quit) {
 544             struct sigaction ignact;
 545
 546             memset(&ignact, 0, sizeof(ignact));
 547             ignact.sa_handler = SIG_IGN;
 548             sigaction(SIGINT, &ignact, &intact);
 549             sigaction(SIGQUIT, &ignact, &quitact);
 550         }
 551
 552         rc = parent(argv[0], parent_ptty, pid, status, log_target,
 553                     abbreviated, file_path);
 554     }
 555
 556     if (ignore_int_quit) {
 557         sigaction(SIGINT, &intact, NULL);
 558         sigaction(SIGQUIT, &quitact, NULL);
 559     }
 560 err_fork:
 561     pthread_sigmask(SIG_SETMASK, &oldset, NULL);
 562 err_child_ptty:
 563 err_ptty:
 564     close(parent_ptty);
 565 err_open:
 566     pthread_mutex_unlock(&fd_mutex);
 567 err_lock:
 568     return rc;
 569 }