src/shared/logprint.c

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