logprint.c

   1 /*
   2  * Copyright 2006, 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 <stdio.h>
  18 #include <stdlib.h>
  19 #include <string.h>
  20 #include <assert.h>
  21 #include <errno.h>
  22 #include <ctype.h>
  23 #include <unistd.h>
  24
  25 #include <logprint.h>
  26
  27
  28 typedef struct FilterInfo_t {
  29     char *mTag;
  30     log_priority mPri;
  31     struct FilterInfo_t *p_next;
  32 } FilterInfo;
  33
  34 struct log_format_t {
  35     log_priority global_pri;
  36     FilterInfo *filters;
  37     log_print_format format;
  38 };
  39
  40 static FilterInfo * filterinfo_new(const char *tag, log_priority pri)
  41 {
  42         FilterInfo *p_ret;
  43         p_ret = (FilterInfo *)calloc(1, sizeof(FilterInfo));
  44         p_ret->mTag = strdup(tag);
  45         p_ret->mPri = pri;
  46
  47         return p_ret;
  48 }
  49
  50 static void filterinfo_free(FilterInfo *p_info)
  51 {
  52         if (p_info == NULL) {
  53                 return;
  54         }
  55
  56         free(p_info->mTag);
  57         p_info->mTag = NULL;
  58 }
  59
  60 /*
  61  * Note: also accepts 0-9 priorities
  62  * returns DLOG_UNKNOWN if the character is unrecognized
  63  */
  64 static log_priority filter_char_to_pri (char c)
  65 {
  66         log_priority pri;
  67
  68         c = tolower(c);
  69
  70         if (c >= '0' && c <= '9') {
  71                 if (c >= ('0'+DLOG_SILENT)) {
  72                         pri = DLOG_VERBOSE;
  73                 } else {
  74                         pri = (log_priority)(c - '0');
  75                 }
  76         } else if (c == 'v') {
  77                 pri = DLOG_VERBOSE;
  78         } else if (c == 'd') {
  79                 pri = DLOG_DEBUG;
  80         } else if (c == 'i') {
  81                 pri = DLOG_INFO;
  82         } else if (c == 'w') {
  83                 pri = DLOG_WARN;
  84         } else if (c == 'e') {
  85                 pri = DLOG_ERROR;
  86         } else if (c == 'f') {
  87                 pri = DLOG_FATAL;
  88         } else if (c == 's') {
  89                 pri = DLOG_SILENT;
  90         } else if (c == '*') {
  91                 pri = DLOG_DEFAULT;
  92         } else {
  93                 pri = DLOG_UNKNOWN;
  94         }
  95
  96         return pri;
  97 }
  98
  99 static char filter_pri_to_char (log_priority pri)
 100 {
 101         switch (pri) {
 102                 case DLOG_VERBOSE:       return 'V';
 103                 case DLOG_DEBUG:         return 'D';
 104                 case DLOG_INFO:          return 'I';
 105                 case DLOG_WARN:          return 'W';
 106                 case DLOG_ERROR:         return 'E';
 107                 case DLOG_FATAL:         return 'F';
 108                 case DLOG_SILENT:        return 'S';
 109
 110                 case DLOG_DEFAULT:
 111                 case DLOG_UNKNOWN:
 112                 default:                        return '?';
 113         }
 114 }
 115
 116 static log_priority filter_pri_for_tag(log_format *p_format, const char *tag)
 117 {
 118     FilterInfo *p_curFilter;
 119 //      log_priority pri = DLOG_SILENT;
 120     for (p_curFilter = p_format->filters; p_curFilter != NULL; p_curFilter = p_curFilter->p_next )
 121         {
 122                 if (0 == strcmp(tag, p_curFilter->mTag))
 123                 {
 124                         if (p_curFilter->mPri == DLOG_DEFAULT) {
 125                                 return p_format->global_pri;
 126                         } else {
 127                                 return p_curFilter->mPri;
 128                         }
 129                 }
 130         }
 131         return p_format->global_pri;
 132 }
 133
 134 /** for debugging */
 135 void dump_filters(log_format *p_format)
 136 {
 137     FilterInfo *p_fi;
 138
 139     for (p_fi = p_format->filters ; p_fi != NULL ; p_fi = p_fi->p_next) {
 140         char cPri = filter_pri_to_char(p_fi->mPri);
 141         if (p_fi->mPri == DLOG_DEFAULT) {
 142             cPri = filter_pri_to_char(p_format->global_pri);
 143         }
 144         fprintf(stderr,"%s:%c\n", p_fi->mTag, cPri);
 145     }
 146
 147     fprintf(stderr,"*:%c\n", filter_pri_to_char(p_format->global_pri));
 148
 149 }
 150
 151 /**
 152  * returns 1 if this log line should be printed based on its priority
 153  * and tag, and 0 if it should not
 154  */
 155 int log_should_print_line (log_format *p_format, const char *tag, log_priority pri)
 156 {
 157     return pri >= filter_pri_for_tag(p_format, tag);
 158 }
 159
 160 log_format *log_format_new()
 161 {
 162     log_format *p_ret;
 163
 164     p_ret = calloc(1, sizeof(log_format));
 165
 166     p_ret->global_pri = DLOG_SILENT;
 167     p_ret->format = FORMAT_BRIEF;
 168
 169     return p_ret;
 170 }
 171
 172 void log_format_free(log_format *p_format)
 173 {
 174     FilterInfo *p_info, *p_info_old;
 175
 176     p_info = p_format->filters;
 177
 178     while (p_info != NULL) {
 179         p_info_old = p_info;
 180         p_info = p_info->p_next;
 181
 182         free(p_info_old);
 183     }
 184
 185     free(p_format);
 186 }
 187
 188 void log_set_print_format(log_format *p_format,log_print_format format)
 189 {
 190     p_format->format=format;
 191 }
 192
 193
 194
 195 /**
 196  * Returns FORMAT_OFF on invalid string
 197  */
 198 log_print_format log_format_from_string(const char * formatString)
 199 {
 200     static log_print_format format;
 201
 202     if (strcmp(formatString, "brief") == 0) format = FORMAT_BRIEF;
 203     else if (strcmp(formatString, "process") == 0) format = FORMAT_PROCESS;
 204     else if (strcmp(formatString, "tag") == 0) format = FORMAT_TAG;
 205     else if (strcmp(formatString, "thread") == 0) format = FORMAT_THREAD;
 206     else if (strcmp(formatString, "raw") == 0) format = FORMAT_RAW;
 207     else if (strcmp(formatString, "time") == 0) format = FORMAT_TIME;
 208     else if (strcmp(formatString, "threadtime") == 0) format = FORMAT_THREADTIME;
 209     else if (strcmp(formatString, "long") == 0) format = FORMAT_LONG;
 210     else format = FORMAT_OFF;
 211
 212     return format;
 213 }
 214
 215 /**
 216  * filterExpression: a single filter expression
 217  * eg "AT:d"
 218  *
 219  * returns 0 on success and -1 on invalid expression
 220  *
 221  * Assumes single threaded execution
 222  */
 223
 224 int log_add_filter_rule(log_format *p_format,
 225         const char *filterExpression)
 226 {
 227 //    size_t i=0;
 228     size_t tagNameLength;
 229     log_priority pri = DLOG_DEFAULT;
 230
 231     tagNameLength = strcspn(filterExpression, ":");
 232
 233     if (tagNameLength == 0) {
 234         goto error;
 235     }
 236
 237     if(filterExpression[tagNameLength] == ':') {
 238         pri = filter_char_to_pri(filterExpression[tagNameLength+1]);
 239
 240         if (pri == DLOG_UNKNOWN) {
 241             goto error;
 242         }
 243     }
 244
 245     if(0 == strncmp("*", filterExpression, tagNameLength)) {
 246         // This filter expression refers to the global filter
 247         // The default level for this is DEBUG if the priority
 248         // is unspecified
 249         if (pri == DLOG_DEFAULT) {
 250             pri = DLOG_DEBUG;
 251         }
 252
 253         p_format->global_pri = pri;
 254     } else {
 255         // for filter expressions that don't refer to the global
 256         // filter, the default is verbose if the priority is unspecified
 257         if (pri == DLOG_DEFAULT) {
 258             pri = DLOG_VERBOSE;
 259         }
 260
 261         char *tagName;
 262         tagName = strndup(filterExpression, tagNameLength);
 263
 264         FilterInfo *p_fi = filterinfo_new(tagName, pri);
 265         free(tagName);
 266
 267         p_fi->p_next = p_format->filters;
 268         p_format->filters = p_fi;
 269     }
 270
 271     return 0;
 272 error:
 273     return -1;
 274 }
 275
 276
 277 /**
 278  * filterString: a comma/whitespace-separated set of filter expressions
 279  *
 280  * eg "AT:d *:i"
 281  *
 282  * returns 0 on success and -1 on invalid expression
 283  *
 284  * Assumes single threaded execution
 285  *
 286  */
 287
 288 int log_add_filter_string(log_format *p_format,
 289         const char *filterString)
 290 {
 291     char *filterStringCopy = strdup (filterString);
 292     char *p_cur = filterStringCopy;
 293     char *p_ret;
 294     int err;
 295
 296     // Yes, I'm using strsep
 297     // FIXME : strtok is more portable than strsep
 298     while (NULL != (p_ret = strsep(&p_cur, " \t,"))) {
 299         // ignore whitespace-only entries
 300         if(p_ret[0] != '\0') {
 301             err = log_add_filter_rule(p_format, p_ret);
 302
 303             if (err < 0) {
 304                 goto error;
 305             }
 306         }
 307     }
 308
 309     free (filterStringCopy);
 310     return 0;
 311 error:
 312     free (filterStringCopy);
 313     return -1;
 314 }
 315
 316 static inline char * strip_end(char *str)
 317 {
 318     char *end = str + strlen(str) - 1;
 319
 320     while (end >= str && isspace(*end))
 321         *end-- = '\0';
 322     return str;
 323 }
 324
 325
 326 /**
 327  * Splits a wire-format buffer into an AndroidLogEntry
 328  * entry allocated by caller. Pointers will point directly into buf
 329  *
 330  * Returns 0 on success and -1 on invalid wire format (entry will be
 331  * in unspecified state)
 332  */
 333 int log_process_log_buffer(struct logger_entry *buf,log_entry *entry)
 334 {
 335     size_t tag_len;
 336
 337     entry->tv_sec = buf->sec;
 338     entry->tv_nsec = buf->nsec;
 339     entry->pid = buf->pid;
 340     entry->tid = buf->tid;
 341
 342     if (buf->msg[0] < 0 || buf->msg[0] > DLOG_SILENT) { /* char can be signed too */
 343
 344          /* There is no tag in this message - which is an error, but it might
 345           * happen when sombody redirects stdout/err to /dev/log_*.
 346           *
 347           * Pick ERROR priority as this shouldn't happen.
 348           */
 349          entry->priority = DLOG_ERROR;
 350          entry->tag = "[NO TAG]";
 351          entry->messageLen = buf->len;
 352          entry->message = buf->msg;
 353     } else {
 354          entry->priority = buf->msg[0];
 355          entry->tag = buf->msg + 1;
 356          tag_len = strlen(entry->tag);
 357          entry->messageLen = buf->len - tag_len - 3;
 358          entry->message = entry->tag + tag_len + 1;
 359     }
 360
 361     return 0;
 362 }
 363
 364
 365 /**
 366  * Formats a log message into a buffer
 367  *
 368  * Uses defaultBuffer if it can, otherwise malloc()'s a new buffer
 369  * If return value != defaultBuffer, caller must call free()
 370  * Returns NULL on malloc error
 371  */
 372
 373 char *log_format_log_line (
 374     log_format *p_format,
 375     char *defaultBuffer,
 376     size_t defaultBufferSize,
 377     const log_entry *entry,
 378     size_t *p_outLength)
 379 {
 380 #if defined(HAVE_LOCALTIME_R)
 381     struct tm tmBuf;
 382 #endif
 383     struct tm* ptm;
 384     char timeBuf[32];
 385  //   char headerBuf[128];
 386     char prefixBuf[128], suffixBuf[128];
 387     char priChar;
 388     int prefixSuffixIsHeaderFooter = 0;
 389     char * ret = NULL;
 390
 391     priChar = filter_pri_to_char(entry->priority);
 392
 393     /*
 394      * Get the current date/time in pretty form
 395      *
 396      * It's often useful when examining a log with "less" to jump to
 397      * a specific point in the file by searching for the date/time stamp.
 398      * For this reason it's very annoying to have regexp meta characters
 399      * in the time stamp.  Don't use forward slashes, parenthesis,
 400      * brackets, asterisks, or other special chars here.
 401      */
 402 #if defined(HAVE_LOCALTIME_R)
 403     ptm = localtime_r(&(entry->tv_sec), &tmBuf);
 404 #else
 405     ptm = localtime(&(entry->tv_sec));
 406 #endif
 407     //strftime(timeBuf, sizeof(timeBuf), "%Y-%m-%d %H:%M:%S", ptm);
 408     strftime(timeBuf, sizeof(timeBuf), "%m-%d %H:%M:%S", ptm);
 409
 410     /*
 411      * Construct a buffer containing the log header and log message.
 412      */
 413     size_t prefixLen, suffixLen;
 414
 415     switch (p_format->format) {
 416         case FORMAT_TAG:
 417             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 418                 "%c/%-8s: ", priChar, entry->tag);
 419             strcpy(suffixBuf, "\n"); suffixLen = 1;
 420             break;
 421         case FORMAT_PROCESS:
 422             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 423                 "%c(%5d) ", priChar, entry->pid);
 424             suffixLen = snprintf(suffixBuf, sizeof(suffixBuf),
 425                 "  (%s)\n", entry->tag);
 426             break;
 427         case FORMAT_THREAD:
 428             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 429                 "%c(%5d:%5d) ", priChar, entry->pid, entry->tid);
 430             strcpy(suffixBuf, "\n");
 431             suffixLen = 1;
 432             break;
 433         case FORMAT_RAW:
 434             prefixBuf[0] = 0;
 435             prefixLen = 0;
 436             strcpy(suffixBuf, "\n");
 437             suffixLen = 1;
 438             break;
 439         case FORMAT_TIME:
 440             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 441                 "%s.%03ld %c/%-8s(%5d): ", timeBuf, entry->tv_nsec / 1000000,
 442                 priChar, entry->tag, entry->pid);
 443             strcpy(suffixBuf, "\n");
 444             suffixLen = 1;
 445             break;
 446         case FORMAT_THREADTIME:
 447             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 448                 "%s.%03ld %5d %5d %c %-8s: ", timeBuf, entry->tv_nsec / 1000000,
 449                 (int)entry->pid, (int)entry->tid, priChar, entry->tag);
 450             strcpy(suffixBuf, "\n");
 451             suffixLen = 1;
 452             break;
 453         case FORMAT_LONG:
 454             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 455                 "[ %s.%03ld %5d:%5d %c/%-8s ]\n",
 456                 timeBuf, entry->tv_nsec / 1000000, entry->pid,
 457                 entry->tid, priChar, entry->tag);
 458             strcpy(suffixBuf, "\n\n");
 459             suffixLen = 2;
 460             prefixSuffixIsHeaderFooter = 1;
 461             break;
 462         case FORMAT_BRIEF:
 463         default:
 464             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 465                 "%c/%-8s(%5d): ", priChar, entry->tag, entry->pid);
 466             strcpy(suffixBuf, "\n");
 467             suffixLen = 1;
 468             break;
 469     }
 470     /* snprintf has a weird return value.   It returns what would have been
 471      * written given a large enough buffer.  In the case that the prefix is
 472      * longer then our buffer(128), it messes up the calculations below
 473      * possibly causing heap corruption.  To avoid this we double check and
 474      * set the length at the maximum (size minus null byte)
 475      */
 476     if(prefixLen >= sizeof(prefixBuf))
 477         prefixLen = sizeof(prefixBuf) - 1;
 478     if(suffixLen >= sizeof(suffixBuf))
 479         suffixLen = sizeof(suffixBuf) - 1;
 480
 481     /* the following code is tragically unreadable */
 482
 483     size_t numLines;
 484 //    size_t i;
 485     char *p;
 486     size_t bufferSize;
 487     const char *pm;
 488
 489     if (prefixSuffixIsHeaderFooter) {
 490         // we're just wrapping message with a header/footer
 491         numLines = 1;
 492     } else {
 493         pm = entry->message;
 494         numLines = 0;
 495
 496         // The line-end finding here must match the line-end finding
 497         // in for ( ... numLines...) loop below
 498         while (pm < (entry->message + entry->messageLen)) {
 499             if (*pm++ == '\n') numLines++;
 500         }
 501         // plus one line for anything not newline-terminated at the end
 502         if (pm > entry->message && *(pm-1) != '\n') numLines++;
 503     }
 504
 505     // this is an upper bound--newlines in message may be counted
 506     // extraneously
 507     bufferSize = (numLines * (prefixLen + suffixLen)) + entry->messageLen + 1;
 508
 509     if (defaultBufferSize >= bufferSize) {
 510         ret = defaultBuffer;
 511     } else {
 512         ret = (char *)malloc(bufferSize);
 513
 514         if (ret == NULL) {
 515             return ret;
 516         }
 517     }
 518
 519     ret[0] = '\0';       /* to start strcat off */
 520
 521     p = ret;
 522     pm = entry->message;
 523
 524     if (prefixSuffixIsHeaderFooter) {
 525         strcat(p, prefixBuf);
 526 //        strncat(p, prefixBuf, sizeof(prefixBuf));
 527         p += prefixLen;
 528         strncat(p, entry->message, entry->messageLen);
 529         p += entry->messageLen;
 530         strcat(p, suffixBuf);
 531 //        strncat(p, suffixBuf, sizeof(suffixBuf));
 532         p += suffixLen;
 533     } else {
 534         while(pm < (entry->message + entry->messageLen)) {
 535             const char *lineStart;
 536             size_t lineLen;
 537
 538             lineStart = pm;
 539
 540             // Find the next end-of-line in message
 541             while (pm < (entry->message + entry->messageLen)
 542                     && *pm != '\n') pm++;
 543             lineLen = pm - lineStart;
 544
 545             strcat(p, prefixBuf);
 546             //strncat(p, prefixBuf, sizeof(prefixBuf));
 547             p += prefixLen;
 548             strncat(p, lineStart, lineLen);
 549             p += lineLen;
 550             strcat(p, suffixBuf);
 551             //strncat(p, suffixBuf, sizeof(suffixBuf));
 552             p += suffixLen;
 553
 554             if (*pm == '\n') pm++;
 555         }
 556     }
 557
 558     if (p_outLength != NULL) {
 559         *p_outLength = p - ret;
 560     }
 561
 562     return ret;
 563 }
 564
 565 /**
 566  * Either print or do not print log line, based on filter
 567  *
 568  * Returns count bytes written
 569  */
 570
 571 int log_print_log_line(
 572     log_format *p_format,
 573     int fd,
 574     const log_entry *entry)
 575 {
 576         int ret;
 577         char defaultBuffer[512];
 578         char *outBuffer = NULL;
 579         size_t totalLen;
 580
 581         outBuffer = log_format_log_line(p_format, defaultBuffer,sizeof(defaultBuffer), entry, &totalLen);
 582
 583         if (!outBuffer)
 584                 return -1;
 585
 586         do {
 587                 ret = write(fd, outBuffer, totalLen);
 588         } while (ret < 0 && errno == EINTR);
 589
 590         if (ret < 0) {
 591                 fprintf(stderr, "+++ LOG: write failed (errno=%d)\n", errno);
 592                 ret = 0;
 593                 goto done;
 594         }
 595
 596         if (((size_t)ret) < totalLen) {
 597                 fprintf(stderr, "+++ LOG: write partial (%d of %d)\n", ret,
 598                 (int)totalLen);
 599                 goto done;
 600         }
 601
 602 done:
 603         if (outBuffer != defaultBuffer) {
 604                 free(outBuffer);
 605         }
 606
 607     return ret;
 608 }
 609
 610
 611
 612 void logprint_run_tests()
 613 {
 614 #if 0
 615
 616     fprintf(stderr, "tests disabled\n");
 617
 618 #else
 619
 620     int err;
 621     const char *tag;
 622     log_format *p_format;
 623
 624     p_format = log_format_new();
 625
 626     fprintf(stderr, "running tests\n");
 627
 628     tag = "random";
 629
 630     log_add_filter_rule(p_format,"*:i");
 631
 632     assert (DLOG_INFO == filter_pri_for_tag(p_format, "random"));
 633     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) == 0);
 634     log_add_filter_rule(p_format, "*");
 635     assert (DLOG_DEBUG == filter_pri_for_tag(p_format, "random"));
 636     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) > 0);
 637     log_add_filter_rule(p_format, "*:v");
 638     assert (DLOG_VERBOSE == filter_pri_for_tag(p_format, "random"));
 639     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) > 0);
 640     log_add_filter_rule(p_format, "*:i");
 641     assert (DLOG_INFO == filter_pri_for_tag(p_format, "random"));
 642     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) == 0);
 643
 644     log_add_filter_rule(p_format, "random");
 645     assert (DLOG_VERBOSE == filter_pri_for_tag(p_format, "random"));
 646     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) > 0);
 647     log_add_filter_rule(p_format, "random:v");
 648     assert (DLOG_VERBOSE == filter_pri_for_tag(p_format, "random"));
 649     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) > 0);
 650     log_add_filter_rule(p_format, "random:d");
 651     assert (DLOG_DEBUG == filter_pri_for_tag(p_format, "random"));
 652     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) > 0);
 653     log_add_filter_rule(p_format, "random:w");
 654     assert (DLOG_WARN == filter_pri_for_tag(p_format, "random"));
 655     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) == 0);
 656
 657     log_add_filter_rule(p_format, "crap:*");
 658     assert (DLOG_VERBOSE== filter_pri_for_tag(p_format, "crap"));
 659     assert(log_should_print_line(p_format, "crap", DLOG_VERBOSE) > 0);
 660
 661     // invalid expression
 662     err = log_add_filter_rule(p_format, "random:z");
 663     assert (err < 0);
 664     assert (DLOG_WARN == filter_pri_for_tag(p_format, "random"));
 665     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) == 0);
 666
 667     // Issue #550946
 668     err = log_add_filter_string(p_format, " ");
 669     assert(err == 0);
 670     assert(DLOG_WARN == filter_pri_for_tag(p_format, "random"));
 671
 672     // note trailing space
 673     err = log_add_filter_string(p_format, "*:s random:d ");
 674     assert(err == 0);
 675     assert(DLOG_DEBUG == filter_pri_for_tag(p_format, "random"));
 676
 677     err = log_add_filter_string(p_format, "*:s random:z");
 678     assert(err < 0);
 679
 680     log_format_free(p_format);
 681
 682
 683 #if 0
 684     char *ret;
 685     char defaultBuffer[512];
 686
 687     ret = log_formatLogLine(p_format,
 688         defaultBuffer, sizeof(defaultBuffer), 0, DLOG_ERROR, 123,
 689         123, 123, "random", "nofile", strlen("Hello"), "Hello", NULL);
 690 #endif
 691
 692
 693     fprintf(stderr, "tests complete\n");
 694 #endif
 695 }
 696