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->priority = buf->msg[0];
 340     entry->pid = buf->pid;
 341     entry->tid = buf->tid;
 342     entry->tag = buf->msg + 1;
 343     tag_len = strlen(entry->tag);
 344     entry->messageLen = buf->len - tag_len - 3;
 345     entry->message = entry->tag + tag_len + 1;
 346
 347     return 0;
 348 }
 349
 350
 351 /**
 352  * Formats a log message into a buffer
 353  *
 354  * Uses defaultBuffer if it can, otherwise malloc()'s a new buffer
 355  * If return value != defaultBuffer, caller must call free()
 356  * Returns NULL on malloc error
 357  */
 358
 359 char *log_format_log_line (
 360     log_format *p_format,
 361     char *defaultBuffer,
 362     size_t defaultBufferSize,
 363     const log_entry *entry,
 364     size_t *p_outLength)
 365 {
 366 #if defined(HAVE_LOCALTIME_R)
 367     struct tm tmBuf;
 368 #endif
 369     struct tm* ptm;
 370     char timeBuf[32];
 371  //   char headerBuf[128];
 372     char prefixBuf[128], suffixBuf[128];
 373     char priChar;
 374     int prefixSuffixIsHeaderFooter = 0;
 375     char * ret = NULL;
 376
 377     priChar = filter_pri_to_char(entry->priority);
 378
 379     /*
 380      * Get the current date/time in pretty form
 381      *
 382      * It's often useful when examining a log with "less" to jump to
 383      * a specific point in the file by searching for the date/time stamp.
 384      * For this reason it's very annoying to have regexp meta characters
 385      * in the time stamp.  Don't use forward slashes, parenthesis,
 386      * brackets, asterisks, or other special chars here.
 387      */
 388 #if defined(HAVE_LOCALTIME_R)
 389     ptm = localtime_r(&(entry->tv_sec), &tmBuf);
 390 #else
 391     ptm = localtime(&(entry->tv_sec));
 392 #endif
 393     //strftime(timeBuf, sizeof(timeBuf), "%Y-%m-%d %H:%M:%S", ptm);
 394     strftime(timeBuf, sizeof(timeBuf), "%m-%d %H:%M:%S", ptm);
 395
 396     /*
 397      * Construct a buffer containing the log header and log message.
 398      */
 399     size_t prefixLen, suffixLen;
 400
 401     switch (p_format->format) {
 402         case FORMAT_TAG:
 403             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 404                 "%c/%-8s: ", priChar, entry->tag);
 405             strcpy(suffixBuf, "\n"); suffixLen = 1;
 406             break;
 407         case FORMAT_PROCESS:
 408             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 409                 "%c(%5d) ", priChar, entry->pid);
 410             suffixLen = snprintf(suffixBuf, sizeof(suffixBuf),
 411                 "  (%s)\n", entry->tag);
 412             break;
 413         case FORMAT_THREAD:
 414             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 415                 "%c(%5d:%5d) ", priChar, entry->pid, entry->tid);
 416             strcpy(suffixBuf, "\n");
 417             suffixLen = 1;
 418             break;
 419         case FORMAT_RAW:
 420             prefixBuf[0] = 0;
 421             prefixLen = 0;
 422             strcpy(suffixBuf, "\n");
 423             suffixLen = 1;
 424             break;
 425         case FORMAT_TIME:
 426             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 427                 "%s.%03ld %c/%-8s(%5d): ", timeBuf, entry->tv_nsec / 1000000,
 428                 priChar, entry->tag, entry->pid);
 429             strcpy(suffixBuf, "\n");
 430             suffixLen = 1;
 431             break;
 432         case FORMAT_THREADTIME:
 433             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 434                 "%s.%03ld %5d %5d %c %-8s: ", timeBuf, entry->tv_nsec / 1000000,
 435                 (int)entry->pid, (int)entry->tid, priChar, entry->tag);
 436             strcpy(suffixBuf, "\n");
 437             suffixLen = 1;
 438             break;
 439         case FORMAT_LONG:
 440             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 441                 "[ %s.%03ld %5d:%5d %c/%-8s ]\n",
 442                 timeBuf, entry->tv_nsec / 1000000, entry->pid,
 443                 entry->tid, priChar, entry->tag);
 444             strcpy(suffixBuf, "\n\n");
 445             suffixLen = 2;
 446             prefixSuffixIsHeaderFooter = 1;
 447             break;
 448         case FORMAT_BRIEF:
 449         default:
 450             prefixLen = snprintf(prefixBuf, sizeof(prefixBuf),
 451                 "%c/%-8s(%5d): ", priChar, entry->tag, entry->pid);
 452             strcpy(suffixBuf, "\n");
 453             suffixLen = 1;
 454             break;
 455     }
 456     /* snprintf has a weird return value.   It returns what would have been
 457      * written given a large enough buffer.  In the case that the prefix is
 458      * longer then our buffer(128), it messes up the calculations below
 459      * possibly causing heap corruption.  To avoid this we double check and
 460      * set the length at the maximum (size minus null byte)
 461      */
 462     if(prefixLen >= sizeof(prefixBuf))
 463         prefixLen = sizeof(prefixBuf) - 1;
 464     if(suffixLen >= sizeof(suffixBuf))
 465         suffixLen = sizeof(suffixBuf) - 1;
 466
 467     /* the following code is tragically unreadable */
 468
 469     size_t numLines;
 470 //    size_t i;
 471     char *p;
 472     size_t bufferSize;
 473     const char *pm;
 474
 475     if (prefixSuffixIsHeaderFooter) {
 476         // we're just wrapping message with a header/footer
 477         numLines = 1;
 478     } else {
 479         pm = entry->message;
 480         numLines = 0;
 481
 482         // The line-end finding here must match the line-end finding
 483         // in for ( ... numLines...) loop below
 484         while (pm < (entry->message + entry->messageLen)) {
 485             if (*pm++ == '\n') numLines++;
 486         }
 487         // plus one line for anything not newline-terminated at the end
 488         if (pm > entry->message && *(pm-1) != '\n') numLines++;
 489     }
 490
 491     // this is an upper bound--newlines in message may be counted
 492     // extraneously
 493     bufferSize = (numLines * (prefixLen + suffixLen)) + entry->messageLen + 1;
 494
 495     if (defaultBufferSize >= bufferSize) {
 496         ret = defaultBuffer;
 497     } else {
 498         ret = (char *)malloc(bufferSize);
 499
 500         if (ret == NULL) {
 501             return ret;
 502         }
 503     }
 504
 505     ret[0] = '\0';       /* to start strcat off */
 506
 507     p = ret;
 508     pm = entry->message;
 509
 510     if (prefixSuffixIsHeaderFooter) {
 511         strcat(p, prefixBuf);
 512 //        strncat(p, prefixBuf, sizeof(prefixBuf));
 513         p += prefixLen;
 514         strncat(p, entry->message, entry->messageLen);
 515         p += entry->messageLen;
 516         strcat(p, suffixBuf);
 517 //        strncat(p, suffixBuf, sizeof(suffixBuf));
 518         p += suffixLen;
 519     } else {
 520         while(pm < (entry->message + entry->messageLen)) {
 521             const char *lineStart;
 522             size_t lineLen;
 523
 524             lineStart = pm;
 525
 526             // Find the next end-of-line in message
 527             while (pm < (entry->message + entry->messageLen)
 528                     && *pm != '\n') pm++;
 529             lineLen = pm - lineStart;
 530
 531             strcat(p, prefixBuf);
 532             //strncat(p, prefixBuf, sizeof(prefixBuf));
 533             p += prefixLen;
 534             strncat(p, lineStart, lineLen);
 535             p += lineLen;
 536             strcat(p, suffixBuf);
 537             //strncat(p, suffixBuf, sizeof(suffixBuf));
 538             p += suffixLen;
 539
 540             if (*pm == '\n') pm++;
 541         }
 542     }
 543
 544     if (p_outLength != NULL) {
 545         *p_outLength = p - ret;
 546     }
 547
 548     return ret;
 549 }
 550
 551 /**
 552  * Either print or do not print log line, based on filter
 553  *
 554  * Returns count bytes written
 555  */
 556
 557 int log_print_log_line(
 558     log_format *p_format,
 559     int fd,
 560     const log_entry *entry)
 561 {
 562         int ret;
 563         char defaultBuffer[512];
 564         char *outBuffer = NULL;
 565         size_t totalLen;
 566
 567         outBuffer = log_format_log_line(p_format, defaultBuffer,sizeof(defaultBuffer), entry, &totalLen);
 568
 569         if (!outBuffer)
 570                 return -1;
 571
 572         do {
 573                 ret = write(fd, outBuffer, totalLen);
 574         } while (ret < 0 && errno == EINTR);
 575
 576         if (ret < 0) {
 577                 fprintf(stderr, "+++ LOG: write failed (errno=%d)\n", errno);
 578                 ret = 0;
 579                 goto done;
 580         }
 581
 582         if (((size_t)ret) < totalLen) {
 583                 fprintf(stderr, "+++ LOG: write partial (%d of %d)\n", ret,
 584                 (int)totalLen);
 585                 goto done;
 586         }
 587
 588 done:
 589         if (outBuffer != defaultBuffer) {
 590                 free(outBuffer);
 591         }
 592
 593     return ret;
 594 }
 595
 596
 597
 598 void logprint_run_tests()
 599 {
 600 #if 0
 601
 602     fprintf(stderr, "tests disabled\n");
 603
 604 #else
 605
 606     int err;
 607     const char *tag;
 608     log_format *p_format;
 609
 610     p_format = log_format_new();
 611
 612     fprintf(stderr, "running tests\n");
 613
 614     tag = "random";
 615
 616     log_add_filter_rule(p_format,"*:i");
 617
 618     assert (DLOG_INFO == filter_pri_for_tag(p_format, "random"));
 619     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) == 0);
 620     log_add_filter_rule(p_format, "*");
 621     assert (DLOG_DEBUG == filter_pri_for_tag(p_format, "random"));
 622     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) > 0);
 623     log_add_filter_rule(p_format, "*:v");
 624     assert (DLOG_VERBOSE == filter_pri_for_tag(p_format, "random"));
 625     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) > 0);
 626     log_add_filter_rule(p_format, "*:i");
 627     assert (DLOG_INFO == filter_pri_for_tag(p_format, "random"));
 628     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) == 0);
 629
 630     log_add_filter_rule(p_format, "random");
 631     assert (DLOG_VERBOSE == filter_pri_for_tag(p_format, "random"));
 632     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) > 0);
 633     log_add_filter_rule(p_format, "random:v");
 634     assert (DLOG_VERBOSE == filter_pri_for_tag(p_format, "random"));
 635     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) > 0);
 636     log_add_filter_rule(p_format, "random:d");
 637     assert (DLOG_DEBUG == filter_pri_for_tag(p_format, "random"));
 638     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) > 0);
 639     log_add_filter_rule(p_format, "random:w");
 640     assert (DLOG_WARN == filter_pri_for_tag(p_format, "random"));
 641     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) == 0);
 642
 643     log_add_filter_rule(p_format, "crap:*");
 644     assert (DLOG_VERBOSE== filter_pri_for_tag(p_format, "crap"));
 645     assert(log_should_print_line(p_format, "crap", DLOG_VERBOSE) > 0);
 646
 647     // invalid expression
 648     err = log_add_filter_rule(p_format, "random:z");
 649     assert (err < 0);
 650     assert (DLOG_WARN == filter_pri_for_tag(p_format, "random"));
 651     assert(log_should_print_line(p_format, tag, DLOG_DEBUG) == 0);
 652
 653     // Issue #550946
 654     err = log_add_filter_string(p_format, " ");
 655     assert(err == 0);
 656     assert(DLOG_WARN == filter_pri_for_tag(p_format, "random"));
 657
 658     // note trailing space
 659     err = log_add_filter_string(p_format, "*:s random:d ");
 660     assert(err == 0);
 661     assert(DLOG_DEBUG == filter_pri_for_tag(p_format, "random"));
 662
 663     err = log_add_filter_string(p_format, "*:s random:z");
 664     assert(err < 0);
 665
 666
 667 #if 0
 668     char *ret;
 669     char defaultBuffer[512];
 670
 671     ret = log_formatLogLine(p_format,
 672         defaultBuffer, sizeof(defaultBuffer), 0, DLOG_ERROR, 123,
 673         123, 123, "random", "nofile", strlen("Hello"), "Hello", NULL);
 674 #endif
 675
 676
 677     fprintf(stderr, "tests complete\n");
 678 #endif
 679 }
 680