libc/bionic/libc_logging.cpp

   1 /*
   2  * Copyright (C) 2010 The Android Open Source Project
   3  * All rights reserved.
   4  *
   5  * Redistribution and use in source and binary forms, with or without
   6  * modification, are permitted provided that the following conditions
   7  * are met:
   8  *  * Redistributions of source code must retain the above copyright
   9  *    notice, this list of conditions and the following disclaimer.
  10  *  * Redistributions in binary form must reproduce the above copyright
  11  *    notice, this list of conditions and the following disclaimer in
  12  *    the documentation and/or other materials provided with the
  13  *    distribution.
  14  *
  15  * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
  16  * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
  17  * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS
  18  * FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE
  19  * COPYRIGHT OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT,
  20  * INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING,
  21  * BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS
  22  * OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED
  23  * AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY,
  24  * OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
  25  * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
  26  * SUCH DAMAGE.
  27  */
  28
  29 #include "../private/libc_logging.h" // Relative path so we can #include this .cpp file for testing.
  30 #include "../private/ScopedPthreadMutexLocker.h"
  31
  32 #include <android/set_abort_message.h>
  33 #include <assert.h>
  34 #include <ctype.h>
  35 #include <errno.h>
  36 #include <fcntl.h>
  37 #include <pthread.h>
  38 #include <stdarg.h>
  39 #include <stddef.h>
  40 #include <stdlib.h>
  41 #include <string.h>
  42 #include <sys/mman.h>
  43 #include <sys/socket.h>
  44 #include <sys/types.h>
  45 #include <sys/uio.h>
  46 #include <sys/un.h>
  47 #include <time.h>
  48 #include <unistd.h>
  49
  50 #define _REALLY_INCLUDE_SYS__SYSTEM_PROPERTIES_H_
  51 #include <sys/_system_properties.h>
  52
  53 static pthread_mutex_t g_abort_msg_lock = PTHREAD_MUTEX_INITIALIZER;
  54
  55 __LIBC_HIDDEN__ abort_msg_t** __abort_message_ptr; // Accessible to __libc_init_common.
  56
  57 // Must be kept in sync with frameworks/base/core/java/android/util/EventLog.java.
  58 enum AndroidEventLogType {
  59   EVENT_TYPE_INT      = 0,
  60   EVENT_TYPE_LONG     = 1,
  61   EVENT_TYPE_STRING   = 2,
  62   EVENT_TYPE_LIST     = 3,
  63   EVENT_TYPE_FLOAT    = 4,
  64 };
  65
  66 struct BufferOutputStream {
  67  public:
  68   BufferOutputStream(char* buffer, size_t size) : total(0) {
  69     buffer_ = buffer;
  70     end_ = buffer + size - 1;
  71     pos_ = buffer_;
  72     pos_[0] = '\0';
  73   }
  74
  75   ~BufferOutputStream() {
  76   }
  77
  78   void Send(const char* data, int len) {
  79     if (len < 0) {
  80       len = strlen(data);
  81     }
  82
  83     total += len;
  84
  85     while (len > 0) {
  86       int avail = end_ - pos_;
  87       if (avail == 0) {
  88         return;
  89       }
  90       if (avail > len) {
  91         avail = len;
  92       }
  93       memcpy(pos_, data, avail);
  94       pos_ += avail;
  95       pos_[0] = '\0';
  96       len -= avail;
  97     }
  98   }
  99
 100   size_t total;
 101
 102  private:
 103   char* buffer_;
 104   char* pos_;
 105   char* end_;
 106 };
 107
 108 struct FdOutputStream {
 109  public:
 110   explicit FdOutputStream(int fd) : total(0), fd_(fd) {
 111   }
 112
 113   void Send(const char* data, int len) {
 114     if (len < 0) {
 115       len = strlen(data);
 116     }
 117
 118     total += len;
 119
 120     while (len > 0) {
 121       int rc = TEMP_FAILURE_RETRY(write(fd_, data, len));
 122       if (rc == -1) {
 123         return;
 124       }
 125       data += rc;
 126       len -= rc;
 127     }
 128   }
 129
 130   size_t total;
 131
 132  private:
 133   int fd_;
 134 };
 135
 136 /*** formatted output implementation
 137  ***/
 138
 139 /* Parse a decimal string from 'format + *ppos',
 140  * return the value, and writes the new position past
 141  * the decimal string in '*ppos' on exit.
 142  *
 143  * NOTE: Does *not* handle a sign prefix.
 144  */
 145 static unsigned parse_decimal(const char *format, int *ppos) {
 146     const char* p = format + *ppos;
 147     unsigned result = 0;
 148
 149     for (;;) {
 150         int ch = *p;
 151         unsigned d = static_cast<unsigned>(ch - '0');
 152
 153         if (d >= 10U) {
 154             break;
 155         }
 156
 157         result = result*10 + d;
 158         p++;
 159     }
 160     *ppos = p - format;
 161     return result;
 162 }
 163
 164 // Writes number 'value' in base 'base' into buffer 'buf' of size 'buf_size' bytes.
 165 // Assumes that buf_size > 0.
 166 static void format_unsigned(char* buf, size_t buf_size, uint64_t value, int base, bool caps) {
 167   char* p = buf;
 168   char* end = buf + buf_size - 1;
 169
 170   // Generate digit string in reverse order.
 171   while (value) {
 172     unsigned d = value % base;
 173     value /= base;
 174     if (p != end) {
 175       char ch;
 176       if (d < 10) {
 177         ch = '0' + d;
 178       } else {
 179         ch = (caps ? 'A' : 'a') + (d - 10);
 180       }
 181       *p++ = ch;
 182     }
 183   }
 184
 185   // Special case for 0.
 186   if (p == buf) {
 187     if (p != end) {
 188       *p++ = '0';
 189     }
 190   }
 191   *p = '\0';
 192
 193   // Reverse digit string in-place.
 194   size_t length = p - buf;
 195   for (size_t i = 0, j = length - 1; i < j; ++i, --j) {
 196     char ch = buf[i];
 197     buf[i] = buf[j];
 198     buf[j] = ch;
 199   }
 200 }
 201
 202 static void format_integer(char* buf, size_t buf_size, uint64_t value, char conversion) {
 203   // Decode the conversion specifier.
 204   int is_signed = (conversion == 'd' || conversion == 'i' || conversion == 'o');
 205   int base = 10;
 206   if (conversion == 'x' || conversion == 'X') {
 207     base = 16;
 208   } else if (conversion == 'o') {
 209     base = 8;
 210   }
 211   bool caps = (conversion == 'X');
 212
 213   if (is_signed && static_cast<int64_t>(value) < 0) {
 214     buf[0] = '-';
 215     buf += 1;
 216     buf_size -= 1;
 217     value = static_cast<uint64_t>(-static_cast<int64_t>(value));
 218   }
 219   format_unsigned(buf, buf_size, value, base, caps);
 220 }
 221
 222 template <typename Out>
 223 static void SendRepeat(Out& o, char ch, int count) {
 224   char pad[8];
 225   memset(pad, ch, sizeof(pad));
 226
 227   const int pad_size = static_cast<int>(sizeof(pad));
 228   while (count > 0) {
 229     int avail = count;
 230     if (avail > pad_size) {
 231       avail = pad_size;
 232     }
 233     o.Send(pad, avail);
 234     count -= avail;
 235   }
 236 }
 237
 238 /* Perform formatted output to an output target 'o' */
 239 template <typename Out>
 240 static void out_vformat(Out& o, const char* format, va_list args) {
 241     int nn = 0;
 242
 243     for (;;) {
 244         int mm;
 245         int padZero = 0;
 246         int padLeft = 0;
 247         char sign = '\0';
 248         int width = -1;
 249         int prec  = -1;
 250         size_t bytelen = sizeof(int);
 251         int slen;
 252         char buffer[32];  /* temporary buffer used to format numbers */
 253
 254         char  c;
 255
 256         /* first, find all characters that are not 0 or '%' */
 257         /* then send them to the output directly */
 258         mm = nn;
 259         do {
 260             c = format[mm];
 261             if (c == '\0' || c == '%')
 262                 break;
 263             mm++;
 264         } while (1);
 265
 266         if (mm > nn) {
 267             o.Send(format+nn, mm-nn);
 268             nn = mm;
 269         }
 270
 271         /* is this it ? then exit */
 272         if (c == '\0')
 273             break;
 274
 275         /* nope, we are at a '%' modifier */
 276         nn++;  // skip it
 277
 278         /* parse flags */
 279         for (;;) {
 280             c = format[nn++];
 281             if (c == '\0') {  /* single trailing '%' ? */
 282                 c = '%';
 283                 o.Send(&c, 1);
 284                 return;
 285             }
 286             else if (c == '0') {
 287                 padZero = 1;
 288                 continue;
 289             }
 290             else if (c == '-') {
 291                 padLeft = 1;
 292                 continue;
 293             }
 294             else if (c == ' ' || c == '+') {
 295                 sign = c;
 296                 continue;
 297             }
 298             break;
 299         }
 300
 301         /* parse field width */
 302         if ((c >= '0' && c <= '9')) {
 303             nn --;
 304             width = static_cast<int>(parse_decimal(format, &nn));
 305             c = format[nn++];
 306         }
 307
 308         /* parse precision */
 309         if (c == '.') {
 310             prec = static_cast<int>(parse_decimal(format, &nn));
 311             c = format[nn++];
 312         }
 313
 314         /* length modifier */
 315         switch (c) {
 316         case 'h':
 317             bytelen = sizeof(short);
 318             if (format[nn] == 'h') {
 319                 bytelen = sizeof(char);
 320                 nn += 1;
 321             }
 322             c = format[nn++];
 323             break;
 324         case 'l':
 325             bytelen = sizeof(long);
 326             if (format[nn] == 'l') {
 327                 bytelen = sizeof(long long);
 328                 nn += 1;
 329             }
 330             c = format[nn++];
 331             break;
 332         case 'z':
 333             bytelen = sizeof(size_t);
 334             c = format[nn++];
 335             break;
 336         case 't':
 337             bytelen = sizeof(ptrdiff_t);
 338             c = format[nn++];
 339             break;
 340         default:
 341             ;
 342         }
 343
 344         /* conversion specifier */
 345         const char* str = buffer;
 346         if (c == 's') {
 347             /* string */
 348             str = va_arg(args, const char*);
 349             if (str == NULL) {
 350                 str = "(null)";
 351             }
 352         } else if (c == 'c') {
 353             /* character */
 354             /* NOTE: char is promoted to int when passed through the stack */
 355             buffer[0] = static_cast<char>(va_arg(args, int));
 356             buffer[1] = '\0';
 357         } else if (c == 'p') {
 358             uint64_t  value = reinterpret_cast<uintptr_t>(va_arg(args, void*));
 359             buffer[0] = '0';
 360             buffer[1] = 'x';
 361             format_integer(buffer + 2, sizeof(buffer) - 2, value, 'x');
 362         } else if (c == 'd' || c == 'i' || c == 'o' || c == 'u' || c == 'x' || c == 'X') {
 363             /* integers - first read value from stack */
 364             uint64_t value;
 365             int is_signed = (c == 'd' || c == 'i' || c == 'o');
 366
 367             /* NOTE: int8_t and int16_t are promoted to int when passed
 368              *       through the stack
 369              */
 370             switch (bytelen) {
 371             case 1: value = static_cast<uint8_t>(va_arg(args, int)); break;
 372             case 2: value = static_cast<uint16_t>(va_arg(args, int)); break;
 373             case 4: value = va_arg(args, uint32_t); break;
 374             case 8: value = va_arg(args, uint64_t); break;
 375             default: return;  /* should not happen */
 376             }
 377
 378             /* sign extension, if needed */
 379             if (is_signed) {
 380                 int shift = 64 - 8*bytelen;
 381                 value = static_cast<uint64_t>((static_cast<int64_t>(value << shift)) >> shift);
 382             }
 383
 384             /* format the number properly into our buffer */
 385             format_integer(buffer, sizeof(buffer), value, c);
 386         } else if (c == '%') {
 387             buffer[0] = '%';
 388             buffer[1] = '\0';
 389         } else {
 390             __assert(__FILE__, __LINE__, "conversion specifier unsupported");
 391         }
 392
 393         /* if we are here, 'str' points to the content that must be
 394          * outputted. handle padding and alignment now */
 395
 396         slen = strlen(str);
 397
 398         if (sign != '\0' || prec != -1) {
 399             __assert(__FILE__, __LINE__, "sign/precision unsupported");
 400         }
 401
 402         if (slen < width && !padLeft) {
 403             char padChar = padZero ? '0' : ' ';
 404             SendRepeat(o, padChar, width - slen);
 405         }
 406
 407         o.Send(str, slen);
 408
 409         if (slen < width && padLeft) {
 410             char padChar = padZero ? '0' : ' ';
 411             SendRepeat(o, padChar, width - slen);
 412         }
 413     }
 414 }
 415
 416 int __libc_format_buffer(char* buffer, size_t buffer_size, const char* format, ...) {
 417   BufferOutputStream os(buffer, buffer_size);
 418   va_list args;
 419   va_start(args, format);
 420   out_vformat(os, format, args);
 421   va_end(args);
 422   return os.total;
 423 }
 424
 425 int __libc_format_buffer_va_list(char* buffer, size_t buffer_size, const char* format,
 426                                  va_list args) {
 427   BufferOutputStream os(buffer, buffer_size);
 428   out_vformat(os, format, args);
 429   return os.total;
 430 }
 431
 432 int __libc_format_fd(int fd, const char* format, ...) {
 433   FdOutputStream os(fd);
 434   va_list args;
 435   va_start(args, format);
 436   out_vformat(os, format, args);
 437   va_end(args);
 438   return os.total;
 439 }
 440
 441 static int __libc_write_stderr(const char* tag, const char* msg) {
 442   iovec vec[4];
 443   vec[0].iov_base = const_cast<char*>(tag);
 444   vec[0].iov_len = strlen(tag);
 445   vec[1].iov_base = const_cast<char*>(": ");
 446   vec[1].iov_len = 2;
 447   vec[2].iov_base = const_cast<char*>(msg);
 448   vec[2].iov_len = strlen(msg);
 449   vec[3].iov_base = const_cast<char*>("\n");
 450   vec[3].iov_len = 1;
 451
 452   int result = TEMP_FAILURE_RETRY(writev(STDERR_FILENO, vec, 4));
 453   return result;
 454 }
 455
 456 static int __libc_open_log_socket() {
 457   // ToDo: Ideally we want this to fail if the gid of the current
 458   // process is AID_LOGD, but will have to wait until we have
 459   // registered this in private/android_filesystem_config.h. We have
 460   // found that all logd crashes thus far have had no problem stuffing
 461   // the UNIX domain socket and moving on so not critical *today*.
 462
 463   int log_fd = TEMP_FAILURE_RETRY(socket(PF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC | SOCK_NONBLOCK, 0));
 464   if (log_fd == -1) {
 465     return -1;
 466   }
 467
 468   union {
 469     struct sockaddr    addr;
 470     struct sockaddr_un addrUn;
 471   } u;
 472   memset(&u, 0, sizeof(u));
 473   u.addrUn.sun_family = AF_UNIX;
 474   strlcpy(u.addrUn.sun_path, "/dev/socket/logdw", sizeof(u.addrUn.sun_path));
 475
 476   if (TEMP_FAILURE_RETRY(connect(log_fd, &u.addr, sizeof(u.addrUn))) != 0) {
 477     close(log_fd);
 478     return -1;
 479   }
 480
 481   return log_fd;
 482 }
 483
 484 struct cache {
 485   const prop_info* pinfo;
 486   uint32_t serial;
 487   char c;
 488 };
 489
 490 static void refresh_cache(struct cache *cache, const char *key)
 491 {
 492   if (!cache->pinfo) {
 493     cache->pinfo = __system_property_find(key);
 494     if (!cache->pinfo) {
 495       return;
 496     }
 497   }
 498   uint32_t serial = __system_property_serial(cache->pinfo);
 499   if (serial == cache->serial) {
 500     return;
 501   }
 502   cache->serial = serial;
 503
 504   char buf[PROP_VALUE_MAX];
 505   __system_property_read(cache->pinfo, 0, buf);
 506   cache->c = buf[0];
 507 }
 508
 509 // Timestamp state generally remains constant, since a change is
 510 // rare, we can accept a trylock failure gracefully.
 511 static pthread_mutex_t lock_clockid = PTHREAD_MUTEX_INITIALIZER;
 512
 513 static clockid_t __android_log_clockid()
 514 {
 515   static struct cache r_time_cache = { NULL, static_cast<uint32_t>(-1), 0 };
 516   static struct cache p_time_cache = { NULL, static_cast<uint32_t>(-1), 0 };
 517   char c;
 518
 519   if (pthread_mutex_trylock(&lock_clockid)) {
 520     // We are willing to accept some race in this context
 521     if (!(c = p_time_cache.c)) {
 522       c = r_time_cache.c;
 523     }
 524   } else {
 525     static uint32_t serial;
 526     uint32_t current_serial = __system_property_area_serial();
 527     if (current_serial != serial) {
 528       refresh_cache(&r_time_cache, "ro.logd.timestamp");
 529       refresh_cache(&p_time_cache, "persist.logd.timestamp");
 530       serial = current_serial;
 531     }
 532     if (!(c = p_time_cache.c)) {
 533       c = r_time_cache.c;
 534     }
 535
 536     pthread_mutex_unlock(&lock_clockid);
 537   }
 538
 539   return (tolower(c) == 'm') ? CLOCK_MONOTONIC : CLOCK_REALTIME;
 540 }
 541
 542 struct log_time { // Wire format
 543   uint32_t tv_sec;
 544   uint32_t tv_nsec;
 545 };
 546
 547 int __libc_write_log(int priority, const char* tag, const char* msg) {
 548   int main_log_fd = __libc_open_log_socket();
 549   if (main_log_fd == -1) {
 550     // Try stderr instead.
 551     return __libc_write_stderr(tag, msg);
 552   }
 553
 554   iovec vec[6];
 555   char log_id = (priority == ANDROID_LOG_FATAL) ? LOG_ID_CRASH : LOG_ID_MAIN;
 556   vec[0].iov_base = &log_id;
 557   vec[0].iov_len = sizeof(log_id);
 558   uint16_t tid = gettid();
 559   vec[1].iov_base = &tid;
 560   vec[1].iov_len = sizeof(tid);
 561   timespec ts;
 562   clock_gettime(__android_log_clockid(), &ts);
 563   log_time realtime_ts;
 564   realtime_ts.tv_sec = ts.tv_sec;
 565   realtime_ts.tv_nsec = ts.tv_nsec;
 566   vec[2].iov_base = &realtime_ts;
 567   vec[2].iov_len = sizeof(realtime_ts);
 568
 569   vec[3].iov_base = &priority;
 570   vec[3].iov_len = 1;
 571   vec[4].iov_base = const_cast<char*>(tag);
 572   vec[4].iov_len = strlen(tag) + 1;
 573   vec[5].iov_base = const_cast<char*>(msg);
 574   vec[5].iov_len = strlen(msg) + 1;
 575
 576   int result = TEMP_FAILURE_RETRY(writev(main_log_fd, vec, sizeof(vec) / sizeof(vec[0])));
 577   close(main_log_fd);
 578   return result;
 579 }
 580
 581 int __libc_format_log_va_list(int priority, const char* tag, const char* format, va_list args) {
 582   char buffer[1024];
 583   BufferOutputStream os(buffer, sizeof(buffer));
 584   out_vformat(os, format, args);
 585   return __libc_write_log(priority, tag, buffer);
 586 }
 587
 588 int __libc_format_log(int priority, const char* tag, const char* format, ...) {
 589   va_list args;
 590   va_start(args, format);
 591   int result = __libc_format_log_va_list(priority, tag, format, args);
 592   va_end(args);
 593   return result;
 594 }
 595
 596 static void __libc_fatal_va_list(const char* prefix, const char* format, va_list args) {
 597   char msg[1024];
 598   BufferOutputStream os(msg, sizeof(msg));
 599
 600   if (prefix) {
 601     os.Send(prefix, strlen(prefix));
 602     os.Send(": ", 2);
 603   }
 604
 605   out_vformat(os, format, args);
 606
 607   // Log to stderr for the benefit of "adb shell" users and gtests.
 608   struct iovec iov[2] = {
 609     { msg, os.total },
 610     { const_cast<char*>("\n"), 1 },
 611   };
 612   TEMP_FAILURE_RETRY(writev(2, iov, 2));
 613
 614   // Log to the log for the benefit of regular app developers (whose stdout and stderr are closed).
 615   __libc_write_log(ANDROID_LOG_FATAL, "libc", msg);
 616
 617   android_set_abort_message(msg);
 618 }
 619
 620 void __libc_fatal(const char* fmt, ...) {
 621   va_list args;
 622   va_start(args, fmt);
 623   __libc_fatal_va_list(nullptr, fmt, args);
 624   va_end(args);
 625   abort();
 626 }
 627
 628 void __fortify_fatal(const char* fmt, ...) {
 629   va_list args;
 630   va_start(args, fmt);
 631   __libc_fatal_va_list("FORTIFY", fmt, args);
 632   va_end(args);
 633   abort();
 634 }
 635
 636 void android_set_abort_message(const char* msg) {
 637   ScopedPthreadMutexLocker locker(&g_abort_msg_lock);
 638
 639   if (__abort_message_ptr == NULL) {
 640     // We must have crashed _very_ early.
 641     return;
 642   }
 643
 644   if (*__abort_message_ptr != NULL) {
 645     // We already have an abort message.
 646     // Assume that the first crash is the one most worth reporting.
 647     return;
 648   }
 649
 650   size_t size = sizeof(abort_msg_t) + strlen(msg) + 1;
 651   void* map = mmap(NULL, size, PROT_READ | PROT_WRITE, MAP_ANON | MAP_PRIVATE, -1, 0);
 652   if (map == MAP_FAILED) {
 653     return;
 654   }
 655
 656   // TODO: if we stick to the current "one-shot" scheme, we can remove this code and
 657   // stop storing the size.
 658   if (*__abort_message_ptr != NULL) {
 659     munmap(*__abort_message_ptr, (*__abort_message_ptr)->size);
 660   }
 661   abort_msg_t* new_abort_message = reinterpret_cast<abort_msg_t*>(map);
 662   new_abort_message->size = size;
 663   strcpy(new_abort_message->msg, msg);
 664   *__abort_message_ptr = new_abort_message;
 665 }