00001
00002
00003
00004
00005
00006
00007
00008
00009
00010
00011
00012
00013
00014
00015
00016
00017
00018 #include <ctype.h>
00019 #include <stdlib.h>
00020 #include <errno.h>
00021 #include <sys/stat.h>
00022 #include <sys/time.h>
00023 #include <sys/types.h>
00024 #include <fcntl.h>
00025 #include <time.h>
00026 #include <algorithm>
00027
00028 #include "config.h"
00029 #include "DebugUtils.h"
00030 #include "Log.h"
00031 #include "compat/inttypes.h"
00032 #include "io/IO.h"
00033 #include "thread/SpinLock.h"
00034 #include "thread/Timer.h"
00035 #include "util/StringBuffer.h"
00036 #include "util/Glob.h"
00037
00041 namespace oasys {
00042
00043
00044 #undef ASSERT
00045 #define ASSERT(x) __log_assert(x, #x, __FILE__, __LINE__)
00046
00047 void
00048 __log_assert(bool x, const char* what, const char* file, int line)
00049 {
00050 if (! (x)) {
00051 fprintf(stderr, "LOGGING ASSERTION FAILED (%s) at %s:%d\n",
00052 what, file, line);
00053 abort();
00054 }
00055 }
00056
00057 level2str_t log_levelnames[] =
00058 {
00059 { "debug", LOG_DEBUG },
00060 { "info", LOG_INFO },
00061 { "notice", LOG_NOTICE },
00062 { "warning", LOG_WARN },
00063 { "warn", LOG_WARN },
00064 { "error", LOG_ERR },
00065 { "err", LOG_ERR },
00066 { "critical",LOG_CRIT },
00067 { "crit", LOG_CRIT },
00068 { "always", LOG_ALWAYS },
00069 { NULL, LOG_INVALID }
00070 };
00071
00072 Log* Log::instance_ = NULL;
00073 bool Log::inited_ = false;
00074 bool Log::__debug_no_panic_on_overflow = false;
00075
00076 Log::Log()
00077 : output_flags_(OUTPUT_PATH | OUTPUT_TIME | OUTPUT_LEVEL),
00078 logfd_(-1),
00079 default_threshold_(LOG_DEFAULT_THRESHOLD)
00080 {
00081 output_lock_ = new SpinLock();
00082 rule_list_ = &rule_lists_[1];
00083 }
00084
00085 void
00086 Log::init(const char* logfile, log_level_t defaultlvl,
00087 const char* prefix, const char* debug_path)
00088 {
00089 Log* log = new Log();
00090 log->do_init(logfile, defaultlvl, prefix, debug_path);
00091 }
00092
00093 void
00094 Log::do_init(const char* logfile, log_level_t defaultlvl,
00095 const char* prefix, const char *debug_path)
00096 {
00097 ASSERT(instance_ == NULL);
00098 ASSERT(!inited_);
00099
00100
00101 logfile_.assign(logfile);
00102 if (logfile_.compare("-") == 0) {
00103 logfd_ = 1;
00104 } else {
00105 logfd_ = open(logfile_.c_str(), O_CREAT | O_WRONLY | O_APPEND,
00106 S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
00107
00108 if (logfd_ < 0) {
00109 fprintf(stderr, "fatal error opening log file '%s': %s\n",
00110 logfile_.c_str(), strerror(errno));
00111 exit(1);
00112 }
00113 }
00114
00115 if (prefix)
00116 prefix_.assign(prefix);
00117
00118 #ifdef NDEBUG
00119 if (defaultlvl == LOG_DEBUG) {
00120 fprintf(stderr, "WARNING: default log level debug invalid for "
00121 "non-debugging build\n");
00122 defaultlvl = LOG_INFO;
00123 }
00124 #endif
00125
00126 default_threshold_ = defaultlvl;
00127 parse_debug_file(debug_path);
00128
00129 inited_ = true;
00130 instance_ = this;
00131 }
00132
00133 Log::~Log()
00134 {
00135 close(logfd_);
00136 logfd_ = -1;
00137
00138 delete output_lock_;
00139 }
00140
00141 void
00142 Log::shutdown()
00143 {
00144 delete instance_;
00145 instance_ = NULL;
00146 inited_ = false;
00147 }
00148
00149 void
00150 Log::parse_debug_file(const char* debug_path)
00151 {
00152
00153
00154 if (debug_path == 0)
00155 debug_path = debug_path_.c_str();
00156
00157
00158 if (debug_path[0] == '\0')
00159 return;
00160
00161
00162 RuleList* old_rule_list = rule_list_;
00163 RuleList* new_rule_list = (rule_list_ == &rule_lists_[0]) ?
00164 &rule_lists_[1] : &rule_lists_[0];
00165
00166 ASSERT(new_rule_list != old_rule_list);
00167 new_rule_list->clear();
00168
00169
00170 if ((debug_path[0] == '~') && (debug_path[1] == '/')) {
00171 char path[256];
00172 const char* home = getenv("HOME");
00173
00174 if (home == 0 || *home == 0) {
00175 home = "/";
00176 }
00177
00178 if (home[strlen(home) - 1] == '/') {
00179
00180 snprintf(path, sizeof(path), "%s%s", home, debug_path + 2);
00181 } else {
00182 snprintf(path, sizeof(path), "%s%s", home, debug_path + 1);
00183 }
00184
00185 debug_path_.assign(path);
00186 debug_path = debug_path_.c_str();
00187 } else {
00188 debug_path_.assign(debug_path);
00189 }
00190
00191
00192 FILE *fp = fopen(debug_path, "r");
00193 if (fp == NULL) {
00194 return;
00195 }
00196
00197 char buf[1024];
00198 int linenum = 0;
00199
00200 while (!feof(fp)) {
00201 if (fgets(buf, sizeof(buf), fp) > 0) {
00202 char *line = buf;
00203 char *logpath;
00204 char *level;
00205 char *rest;
00206
00207 ++linenum;
00208
00209 logpath = line;
00210
00211
00212 while (*logpath && isspace(*logpath)) ++logpath;
00213 if (! *logpath) {
00214
00215 continue;
00216 }
00217
00218
00219 if (logpath[0] == '#')
00220 continue;
00221
00222
00223 if (logpath[0] == '%') {
00224 if (strstr(logpath, "no_path") != 0) {
00225 output_flags_ &= ~OUTPUT_PATH;
00226 }
00227 if (strstr(logpath, "no_time") != 0) {
00228 output_flags_ &= ~OUTPUT_TIME;
00229 }
00230 if (strstr(logpath, "no_level") != 0) {
00231 output_flags_ &= ~OUTPUT_LEVEL;
00232 }
00233 if (strstr(logpath, "brief") != 0) {
00234 output_flags_ |= OUTPUT_SHORT;
00235 }
00236 if (strstr(logpath, "color") != 0) {
00237 output_flags_ |= OUTPUT_COLOR;
00238 }
00239 if (strstr(logpath, "object") != 0) {
00240 output_flags_ |= OUTPUT_OBJ;
00241 }
00242 if (strstr(logpath, "classname") != 0) {
00243 output_flags_ |= OUTPUT_CLASSNAME;
00244 }
00245 if (strstr(logpath, "walltime") != 0) {
00246 output_flags_ |= OUTPUT_WALLTIME;
00247 }
00248
00249 continue;
00250 }
00251
00252
00253 level = logpath;
00254 while (*level && !isspace(*level)) ++level;
00255 *level = '\0';
00256 ++level;
00257
00258
00259 while (level && isspace(*level)) ++level;
00260 if (!level) {
00261 parse_err:
00262 fprintf(stderr, "Error in log configuration %s line %d\n",
00263 debug_path, linenum);
00264 continue;
00265 }
00266
00267
00268 rest = level;
00269 while (rest && !isspace(*rest)) ++rest;
00270 if (rest) *rest = '\0';
00271
00272 log_level_t threshold = str2level(level);
00273 if (threshold == LOG_INVALID) {
00274 goto parse_err;
00275 }
00276
00277 #ifdef NDEBUG
00278 if (threshold == LOG_DEBUG) {
00279 fprintf(stderr, "WARNING: debug level log rule for path %s "
00280 "ignored in non-debugging build\n",
00281 logpath);
00282 continue;
00283 }
00284 #endif
00285
00286 new_rule_list->push_back(Rule(logpath, threshold));
00287 }
00288 }
00289
00290 fclose(fp);
00291
00292 sort_rules(new_rule_list);
00293
00294 if (inited_) {
00295 logf("/log", LOG_ALWAYS, "reparsed debug file... found %d rules",
00296 (int)new_rule_list->size());
00297 }
00298
00299 rule_list_ = new_rule_list;
00300 }
00301
00302 bool
00303 Log::rule_compare(const Rule& rule1, const Rule& rule2)
00304 {
00305 if (rule1.path_.length() > rule2.path_.length())
00306 return true;
00307
00308 if ((rule1.path_.length() == rule2.path_.length()) &&
00309 (rule1.level_ < rule2.level_))
00310 return true;
00311
00312 return false;
00313 }
00314
00315 void
00316 Log::sort_rules(RuleList* rule_list)
00317 {
00318
00319
00320 std::sort(rule_list->begin(), rule_list->end(), Log::rule_compare);
00321
00322 #ifndef NDEBUG
00323
00324 if (rule_list->size() > 0) {
00325 RuleList::iterator itr;
00326 Rule* prev = 0;
00327 for (itr = rule_list->begin(); itr != rule_list->end(); ++itr) {
00328 if (prev != 0) {
00329 ASSERT(prev->path_.length() >= itr->path_.length());
00330 prev = &(*itr);
00331 }
00332 }
00333 }
00334 #endif // NDEBUG
00335 }
00336
00337 void
00338 Log::dump_rules(StringBuffer* buf)
00339 {
00340 ASSERT(inited_);
00341
00342 RuleList* rule_list = rule_list_;
00343 RuleList::iterator iter = rule_list->begin();
00344 for (iter = rule_list->begin(); iter != rule_list->end(); iter++) {
00345 buf->appendf("%s %s\n", iter->path_.c_str(), level2str(iter->level_));
00346 }
00347 }
00348
00349 Log::Rule *
00350 Log::find_rule(const char *path)
00351 {
00352 ASSERT(inited_);
00353
00354
00355
00356
00357
00358 size_t pathlen = strlen(path);
00359
00360 RuleList::iterator iter;
00361 Rule* rule;
00362 RuleList* rule_list = rule_list_;
00363 for (iter = rule_list->begin(); iter != rule_list->end(); iter++)
00364 {
00365 rule = &(*iter);
00366
00367 if (rule->path_.length() > pathlen) {
00368 continue;
00369 }
00370
00371 const char* rule_path = rule->path_.data();
00372 size_t rulelen = rule->path_.length();
00373
00374 size_t minlen = (pathlen < rulelen) ? pathlen : rulelen;
00375
00376 if (strncmp(rule_path, path, minlen) == 0)
00377 {
00378 return rule;
00379 }
00380
00381
00382
00383
00384 if (rule_path[0] == '+' &&
00385 Glob::fixed_glob(rule_path + 1, path))
00386 {
00387 return rule;
00388 }
00389 }
00390
00391 return NULL;
00392 }
00393
00394 void
00395 Log::redirect_stdio()
00396 {
00397 stdio_redirected_ = true;
00398
00399 ASSERT(logfd_ >= 0);
00400
00401 int err;
00402 if ((err = dup2(logfd_, 1)) != 1) {
00403 logf("/log", LOG_ERR, "error redirecting stdout: %s", strerror(errno));
00404 }
00405
00406 if ((err = dup2(logfd_, 2)) != 2) {
00407 logf("/log", LOG_ERR, "error redirecting stderr: %s", strerror(errno));
00408 }
00409 }
00410
00411 void
00412 Log::rotate()
00413 {
00414 if (logfd_ == 1) {
00415 logf("/log", LOG_WARN, "can't rotate when using stdout for logging");
00416 return;
00417 }
00418
00419 int newfd = open(logfile_.c_str(), O_CREAT | O_WRONLY | O_APPEND,
00420 S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
00421
00422 if (newfd < 0) {
00423 logf("/log", LOG_ERR, "error re-opening log file for rotate: %s",
00424 strerror(errno));
00425 logf("/log", LOG_ERR, "keeping old log file open");
00426 return;
00427 }
00428
00429 output_lock_->lock("Log::rotate");
00430
00431 logf("/log", LOG_NOTICE, "closing log file for rotation");
00432 close(logfd_);
00433
00434 logfd_ = newfd;
00435 logf("/log", LOG_NOTICE, "log rotate successfully reopened file");
00436
00437
00438 if (stdio_redirected_) {
00439 redirect_stdio();
00440 }
00441
00442 output_lock_->unlock();
00443 }
00444
00445 static void
00446 rotate_handler(int sig)
00447 {
00448 (void)sig;
00449 Log::instance()->rotate();
00450 }
00451
00452 void
00453 Log::add_rotate_handler(int sig)
00454 {
00455 logf("/log", LOG_DEBUG, "adding log rotate signal handler");
00456 TimerSystem::instance()->add_sighandler(sig, rotate_handler);
00457 }
00458
00459 static RETSIGTYPE
00460 reparse_handler(int sig)
00461 {
00462 (void)sig;
00463 Log::instance()->parse_debug_file();
00464 }
00465
00466 void
00467 Log::add_reparse_handler(int sig)
00468 {
00469 logf("/log", LOG_DEBUG, "adding log reparse signal handler");
00470 TimerSystem::instance()->add_sighandler(sig, reparse_handler);
00471 }
00472
00473 log_level_t
00474 Log::log_level(const char *path)
00475 {
00476 Rule *r = find_rule(path);
00477
00478 if (r) {
00479 return r->level_;
00480 } else {
00481 return default_threshold_;
00482 }
00483 }
00484
00485 void
00486 Log::getlogtime(struct timeval* tv)
00487 {
00488
00489 ::gettimeofday(tv, 0);
00490 }
00491
00492 size_t
00493 Log::gen_prefix(char* buf, size_t buflen,
00494 const char* path, log_level_t level,
00495 const char* classname, const void* obj)
00496 {
00497 size_t len;
00498 char *ptr = buf;
00499
00500 char* color_begin = "";
00501 char* color_end = "";
00502 char* color_level = "";
00503
00504 if (output_flags_ & OUTPUT_COLOR) {
00505 color_begin = "\033[33m";
00506 color_end = "\033[0m";
00507 color_level = "\033[36m";
00508 }
00509
00510 if (prefix_.size() > 0) {
00511 len = snprintf(ptr, buflen, "%s[%s ", color_begin, prefix_.c_str());
00512 } else {
00513 len = snprintf(ptr, buflen, "%s[", color_begin);
00514 }
00515
00516 buflen -= len;
00517 ptr += len;
00518
00519 if (output_flags_ & OUTPUT_TIME) {
00520 struct timeval tv;
00521 getlogtime(&tv);
00522 if (output_flags_ & OUTPUT_WALLTIME) {
00523 struct tm walltime;
00524 gmtime_r(&tv.tv_sec, &walltime);
00525 len = snprintf(ptr, buflen,
00526 "%02d:%02d:%02d.%03ld ",
00527 walltime.tm_hour, walltime.tm_min,
00528 walltime.tm_sec, (long)tv.tv_usec / 1000);
00529 } else {
00530 len = snprintf(ptr, buflen,
00531 "%ld.%06ld ",
00532 (long)tv.tv_sec, (long)tv.tv_usec);
00533 }
00534
00535 buflen -= len;
00536 ptr += len;
00537 }
00538
00539 if (output_flags_ & OUTPUT_PATH)
00540 {
00541 if (output_flags_ & OUTPUT_SHORT) {
00542 len = snprintf(ptr, buflen, "%-19.19s ", path);
00543 } else {
00544 len = snprintf(ptr, buflen, "%s ", path);
00545 }
00546 buflen -= len;
00547 ptr += len;
00548 }
00549
00550 if (output_flags_ & OUTPUT_CLASSNAME)
00551 {
00552 if (output_flags_ & OUTPUT_SHORT) {
00553 len = snprintf(ptr, buflen, "%-19.19s ",
00554 classname ? classname : "(No_Class)");
00555 } else {
00556 len = snprintf(ptr, buflen, "%s ",
00557 classname ? classname : "(No_Class)");
00558 }
00559 buflen -= len;
00560 ptr += len;
00561 }
00562
00563 if ((output_flags_ & OUTPUT_OBJ) && (obj != NULL))
00564 {
00565 len = snprintf(ptr, buflen, "%p ", obj);
00566 buflen -= len;
00567 ptr += len;
00568 }
00569
00570 if (output_flags_ & OUTPUT_LEVEL)
00571 {
00572 if (output_flags_ & OUTPUT_SHORT) {
00573 len = snprintf(ptr, buflen, "%s%c%s",
00574 color_level,
00575 toupper(level2str(level)[0]),
00576 color_begin);
00577 } else {
00578 len = snprintf(ptr, buflen, "%s%s%s",
00579 color_level,
00580 level2str(level),
00581 color_begin);
00582 }
00583 buflen -= len;
00584 ptr += len;
00585 }
00586
00587 len = snprintf(ptr, buflen, "]%s ", color_end);
00588 buflen -= len;
00589 ptr += len;
00590
00591 return ptr - buf;
00592 }
00593
00594 int
00595 Log::vlogf(const char* path, log_level_t level,
00596 const char* classname, const void* obj,
00597 const char* fmt, va_list ap)
00598 {
00599 ASSERT(inited_);
00600
00601 char pathbuf[LOG_MAX_PATHLEN];
00602
00603
00604
00605 static const char guard[] = "[guard]";
00606 char buf[LOG_MAX_LINELEN + sizeof(guard)];
00607 memcpy(&buf[LOG_MAX_LINELEN], guard, sizeof(guard));
00608 char* ptr = buf;
00609
00610
00611 if (*path != '/') {
00612 snprintf(pathbuf, sizeof pathbuf, "/%s", path);
00613 path = pathbuf;
00614 }
00615
00616
00617 if (! log_enabled(level, path) &&
00618 (classname == NULL || ! log_enabled(level, classname)))
00619 {
00620 return 0;
00621 }
00622
00623 size_t buflen = LOG_MAX_LINELEN - 1;
00624 size_t len;
00625
00626
00627 len = gen_prefix(buf, buflen, path, level, classname, obj);
00628 buflen -= len;
00629 ptr += len;
00630
00631
00632 len = vsnprintf(ptr, buflen, fmt, ap);
00633
00634 if (len >= buflen) {
00635
00636
00637 const char* trunc = "... (truncated)\n";
00638 len = strlen(trunc);
00639 strncpy(&buf[LOG_MAX_LINELEN - len - 1], trunc, len + 1);
00640 buflen = LOG_MAX_LINELEN - 1;
00641 buf[LOG_MAX_LINELEN - 1] = '\0';
00642
00643 } else {
00644
00645 buflen -= len;
00646 ptr += len;
00647 ASSERT(ptr <= (buf + LOG_MAX_LINELEN - 2));
00648
00649 if (ptr[-1] != '\n') {
00650 *ptr++ = '\n';
00651 *ptr = 0;
00652 }
00653
00654 buflen = ptr - buf;
00655 }
00656
00657 #ifndef NDEBUG
00658 if (memcmp(&buf[LOG_MAX_LINELEN], guard, sizeof(guard)) != 0) {
00659 if (__debug_no_panic_on_overflow) {
00660 return -1;
00661 }
00662
00663 PANIC("logf buffer overflow");
00664 }
00665
00666 #endif
00667
00668 #ifdef CHECK_NON_PRINTABLE
00669 for (u_int i = 0; i < buflen; ++i) {
00670 ASSERT(buf[i] == '\n' ||
00671 (buf[i] >= 32 && buf[i] <= 126));
00672 }
00673 #endif
00674
00675
00676
00677
00678 output_lock_->lock("Log::vlogf");
00679 int ret = IO::writeall(logfd_, buf, buflen);
00680 output_lock_->unlock();
00681
00682 ASSERTF(ret == (int)buflen,
00683 "unexpected return from IO::writeall (got %d, expected %zu): %s",
00684 ret, buflen, strerror(errno));
00685
00686 return buflen;
00687 };
00688
00689 int
00690 Log::log_multiline(const char* path, log_level_t level,
00691 const char* classname, const void* obj,
00692 const char* msg)
00693 {
00694 ASSERT(inited_);
00695
00696 char pathbuf[LOG_MAX_PATHLEN];
00697
00698
00699 if (*path != '/') {
00700 snprintf(pathbuf, sizeof pathbuf, "/%s", path);
00701 path = pathbuf;
00702 }
00703
00704
00705 if (! log_enabled(level, path))
00706 return 0;
00707
00708
00709 char prefix[LOG_MAX_LINELEN];
00710 size_t prefix_len = gen_prefix(prefix, sizeof(prefix),
00711 path, level, classname, obj);
00712
00713 size_t iov_total = 128;
00714 struct iovec static_iov[iov_total];
00715 struct iovec* dynamic_iov = NULL;
00716 struct iovec* iov = static_iov;
00717 size_t iov_cnt = 0;
00718 size_t total_len = 0;
00719
00720
00721
00722 const char* end = msg;
00723 while (*msg != '\0') {
00724 end = strchr(msg, '\n');
00725 if (end == NULL) {
00726 PANIC("multiline log message must end in trailing newline");
00727 }
00728 iov[iov_cnt].iov_base = prefix;
00729 iov[iov_cnt].iov_len = prefix_len;
00730 ++iov_cnt;
00731 total_len += prefix_len;
00732
00733 iov[iov_cnt].iov_base = (char*)msg;
00734 iov[iov_cnt].iov_len = end - msg + 1;
00735 ++iov_cnt;
00736 total_len += end - msg + 1;
00737
00738 msg = end + 1;
00739
00740 if (iov_cnt == iov_total) {
00741 PANIC("XXX/demmer implement dynamic_iov for > 64 lines");
00742 (void)dynamic_iov;
00743 }
00744 }
00745
00746
00747
00748
00749 output_lock_->lock("Log::log_multiline");
00750 int ret = IO::writevall(logfd_, iov, iov_cnt);
00751 output_lock_->unlock();
00752
00753 ASSERTF(ret == (int)total_len,
00754 "unexpected return from IO::writevall (got %d, expected %zu): %s",
00755 ret, total_len, strerror(errno));
00756
00757 return ret;
00758 }
00759
00760 }