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