src/xbt/log.c

   1 /* $Id$ */
   2
   3 /* log - a generic logging facility in the spirit of log4j                  */
   4
   5 /* Copyright (c) 2003, 2004 Martin Quinson. All rights reserved.            */
   6
   7 /* This program is free software; you can redistribute it and/or modify it
   8  * under the terms of the license (GNU LGPL) which comes with this package. */
   9
  10 #include <stdarg.h>
  11 #include <ctype.h>
  12
  13 #include "xbt_modinter.h"
  14
  15 #include "xbt/misc.h"
  16 #include "xbt/sysdep.h"
  17 #include "xbt/log.h"
  18 #include "xbt/error.h"
  19 #include "xbt/dynar.h"
  20
  21 /** \addtogroup XBT_log
  22  *
  23  *  This section describes the API to the log functions used
  24  *  everywhere in this project.
  25
  26 \section log_overview Overview
  27
  28 This is an adaptation of the log4c project, which is dead upstream, and
  29 which I was given the permission to fork under the LGPL licence by the
  30 authors. log4c itself was loosely based on the Apache project's Log4J,
  31 Log4CC, etc. project. Because C is not object oriented, a lot had to change.
  32
  33 There is 3 main concepts: category, priority and appender. These three
  34 concepts work together to enable developers to log messages according to
  35 message type and priority, and to control at runtime how these messages are
  36 formatted and where they are reported.
  37
  38 \section log_cat Category hierarchy
  39
  40 The first and foremost advantage of any logging API over plain printf()
  41 resides in its ability to disable certain log statements while allowing
  42 others to print unhindered. This capability assumes that the logging space,
  43 that is, the space of all possible logging statements, is categorized
  44 according to some developer-chosen criteria.
  45
  46 This observation led to choosing category as the central concept of the
  47 system. Every category is declared by providing a name and an optional
  48 parent. If no parent is explicitly named, the root category, LOG_ROOT_CAT is
  49 the category's parent.
  50
  51 A category is created by a macro call at the top level of a file.  A
  52 category can be created with any one of the following macros:
  53
  54  - \ref XBT_LOG_NEW_CATEGORY(MyCat); Create a new root
  55  - \ref XBT_LOG_NEW_SUBCATEGORY(MyCat, ParentCat);
  56     Create a new category being child of the category ParentCat
  57  - \ref XBT_LOG_NEW_DEFAULT_CATEGORY(MyCat);
  58     Like XBT_LOG_NEW_CATEGORY, but the new category is the default one
  59       in this file
  60  -  \ref XBT_LOG_NEW_DEFAULT_SUBCATEGORY(MyCat, ParentCat);
  61     Like XBT_LOG_NEW_SUBCATEGORY, but the new category is the default one
  62       in this file
  63
  64 The parent cat can be defined in the same file or in another file (in
  65 which case you want to use the \ref XBT_LOG_EXTERNAL_CATEGORY macro to make
  66 it visible in the current file), but each category may have only one
  67 definition.
  68
  69 Typically, there will be a Category for each module and sub-module, so you
  70 can independently control logging for each module.
  71
  72 For a list of all existing categories, please refer to the \ref XBT_log_cats section.
  73
  74 \section log_pri Priority
  75
  76 A category may be assigned a threshold priorty. The set of priorites are
  77 defined by the \ref e_xbt_log_priority_t enum. All logging request under
  78 this priority will be discarded.
  79
  80 If a given category is not assigned a threshold priority, then it inherits
  81 one from its closest ancestor with an assigned threshold. To ensure that all
  82 categories can eventually inherit a threshold, the root category always has
  83 an assigned threshold priority.
  84
  85 Logging requests are made by invoking a logging macro on a category.  All of
  86 the macros have a printf-style format string followed by arguments. If you
  87 compile with the -Wall option, gcc will warn you for unmatched arguments, ie
  88 when you pass a pointer to a string where an integer was specified by the
  89 format. This is usualy a good idea.
  90
  91 Because most C compilers do not support vararg macros, there is a version of
  92 the macro for any number of arguments from 0 to 6. The macro name ends with
  93 the total number of arguments.
  94
  95 Here is an example of the most basic type of macro. This is a logging
  96 request with priority <i>warning</i>.
  97
  98 <code>CLOG5(MyCat, gras_log_priority_warning, "Values are: %d and '%s'", 5,
  99 "oops");</code>
 100
 101 A logging request is said to be enabled if its priority is higher than or
 102 equal to the threshold priority of its category. Otherwise, the request is
 103 said to be disabled. A category without an assigned priority will inherit
 104 one from the hierarchy.
 105
 106 It is possible to use any non-negative integer as a priority. If, as in the
 107 example, one of the standard priorites is used, then there is a convenience
 108 macro that is typically used instead. For example, the above example is
 109 equivalent to the shorter:
 110
 111 <code>CWARN4(MyCat, "Values are: %d and '%s'", 5, "oops");</code>
 112
 113 \subsection log_subcat Using a default category
 114
 115 If \ref XBT_LOG_NEW_DEFAULT_SUBCATEGORY(MyCat, Parent) or
 116 \ref XBT_LOG_NEW_DEFAULT_CATEGORY(MyCat) is used to create the
 117 category, then the even shorter form can be used:
 118
 119 <code>WARN3("Values are: %d and '%s'", 5, "oops");</code>
 120
 121 Only one default category can be created per file, though multiple
 122 non-defaults can be created and used.
 123
 124 \section log_example Example
 125
 126 Here is a more complete example:
 127
 128 \verbatim
 129 #include "xbt/log.h"
 130
 131 / * create a category and a default subcategory * /
 132 XBT_LOG_NEW_CATEGORY(VSS);
 133 XBT_LOG_NEW_DEFAULT_SUBCATEGORY(SA, VSS);
 134
 135 int main() {
 136        / * Now set the parent's priority.  (the string would typcially be a runtime option) * /
 137        xbt_log_control_set("SA.thresh=3");
 138
 139        / * This request is enabled, because WARNING &gt;= INFO. * /
 140        CWARN2(VSS, "Low fuel level.");
 141
 142        / * This request is disabled, because DEBUG &lt; INFO. * /
 143        CDEBUG2(VSS, "Starting search for nearest gas station.");
 144
 145        / * The default category SA inherits its priority from VSS. Thus,
 146           the following request is enabled because INFO &gt;= INFO.  * /
 147        INFO1("Located nearest gas station.");
 148
 149        / * This request is disabled, because DEBUG &lt; INFO. * /
 150        DEBUG1("Exiting gas station search");
 151 }
 152 \endverbatim
 153
 154 \section log_conf Configuration
 155 Configuration is typically done during program initialization by invoking
 156 the xbt_log_control_set() method. The control string passed to it typically
 157 comes from the command line. Look at the documentation for that function for
 158 the format of the control string.
 159
 160 Any SimGrid program can furthermore be configured at run time by passing a
 161 --xbt-log argument on the command line (--gras-log, --msg-log and
 162 --surf-log are synonyms). You can provide several of those arguments to
 163 change the setting of several categories.
 164
 165 \section log_perf Performance
 166
 167 Clever design insures efficiency. Except for the first invocation, a
 168 disabled logging request requires an a single comparison of a static
 169 variable to a constant.
 170
 171 There is also compile time constant, \ref XBT_LOG_STATIC_THRESHOLD, which
 172 causes all logging requests with a lower priority to be optimized to 0 cost
 173 by the compiler. By setting it to gras_log_priority_infinite, all logging
 174 requests are statically disabled and cost nothing. Released executables
 175 might be compiled with
 176 \verbatim-DXBT_LOG_STATIC_THRESHOLD=gras_log_priority_infinite\endverbatim
 177
 178 Compiling with the \verbatim-DNLOG\endverbatim option disables all logging
 179 requests at compilation time while the \verbatim-DNDEBUG\endverbatim disables
 180 the requests of priority below INFO.
 181
 182 \section log_app Appenders
 183
 184 Each category has an optional appender. An appender is a pointer to a
 185 structure which starts with a pointer to a doAppend() function. DoAppend()
 186 prints a message to a log.
 187
 188 When a category is passed a message by one of the logging macros, the
 189 category performs the following actions:
 190
 191   - if the category has an appender, the message is passed to the
 192     appender's doAppend() function,
 193   - if 'willLogToParent' is true for the category, the message is passed
 194     to the category's parent.
 195
 196 By default, only the root category have an appender, and 'willLogToParent'
 197 is true for any other category. This situation causes all messages to be
 198 logged by the root category's appender.
 199
 200 The default appender function currently prints to stderr, and no other one
 201 exist, even if more would be needed, like the one able to send the logs to a
 202 remote dedicated server, or other ones offering different output formats.
 203 This is on our TODO list for quite a while now, but your help would be
 204 welcome here.
 205
 206 \section log_misc Misc and Caveats
 207
 208   - Do not use any of the macros that start with '_'.
 209   - Log4J has a 'rolling file appender' which you can select with a run-time
 210     option and specify the max file size. This would be a nice default for
 211     non-kernel applications.
 212   - Careful, category names are global variables.
 213
 214 */
 215
 216 /*
 217 FAIRE DES ZOLIS LOGS
 218 --------------------
 219 Pour utiliser les logs, tu déjà faire, non ? Tu colle sur la ligne de
 220 commande un ou plusieurs arguments de la forme
 221   --gras-log="<réglage> [<reglage>+]" (ou sans " si t'as pas d'espace)
 222 chaque réglage étant de la forme:
 223   <canal>.thres=<priorité>
 224 Les différents réglages sont lus de gauche à droite.
 225 "root.thres=debug root.thres=critical" ferme tout, normalement.
 226
 227 */
 228
 229 typedef struct {
 230   char *catname;
 231   e_xbt_log_priority_t thresh;
 232 } s_xbt_log_setting_t,*xbt_log_setting_t;
 233
 234 static xbt_dynar_t xbt_log_settings=NULL;
 235 static void _free_setting(void *s) {
 236   xbt_log_setting_t set=(xbt_log_setting_t)s;
 237   if (set) {
 238     free(set->catname);
 239 /*    free(set); FIXME: uncommenting this leads to segfault when more than one chunk is passed as gras-log */
 240   }
 241 }
 242
 243 const char *xbt_log_priority_names[8] = {
 244   "NONE",
 245   "TRACE",
 246   "DEBUG",
 247   "VERBOSE",
 248   "INFO",
 249   "WARNING",
 250   "ERROR",
 251   "CRITICAL"
 252 };
 253
 254 s_xbt_log_category_t _XBT_LOGV(XBT_LOG_ROOT_CAT) = {
 255   0, 0, 0,
 256   "root", xbt_log_priority_uninitialized, 0,
 257   NULL, 0
 258 };
 259
 260 XBT_LOG_NEW_CATEGORY(xbt,"All XBT categories (simgrid toolbox)");
 261 XBT_LOG_NEW_CATEGORY(surf,"All SURF categories");
 262 XBT_LOG_NEW_CATEGORY(msg,"All MSG categories");
 263 XBT_LOG_NEW_DEFAULT_SUBCATEGORY(log,xbt,"Loggings from the logging mechanism itself");
 264
 265 void xbt_log_init(int *argc,char **argv, const char *defaultlog) {
 266   int i,j;
 267   char *opt;
 268   int found=0;
 269
 270   /* Set logs and init log submodule */
 271   for (i=1; i<*argc; i++) {
 272     if (!strncmp(argv[i],"--gras-log=",strlen("--gras-log=")) ||
 273         !strncmp(argv[i],"--surf-log=",strlen("--surf-log=")) ||
 274         !strncmp(argv[i],"--msg-log=",strlen("--msg-log=")) ||
 275         !strncmp(argv[i],"--xbt-log=",strlen("--xbt-log="))) {
 276       found = 1;
 277       opt=strchr(argv[i],'=');
 278       opt++;
 279       xbt_log_control_set(opt);
 280       DEBUG1("Did apply '%s' as log setting",opt);
 281       /*remove this from argv*/
 282       for (j=i+1; j<*argc; j++) {
 283         argv[j-1] = argv[j];
 284       }
 285       argv[j-1] = NULL;
 286       (*argc)--;
 287       i--; /* compensate effect of next loop incrementation */
 288     }
 289   }
 290   if (!found && defaultlog) {
 291      xbt_log_control_set(defaultlog);
 292   }
 293 }
 294
 295 void xbt_log_exit(void) {
 296   VERB0("Exiting log");
 297   xbt_dynar_free(&xbt_log_settings);
 298   VERB0("Exited log");
 299 }
 300
 301 static void _apply_control(xbt_log_category_t cat) {
 302   int cursor;
 303   xbt_log_setting_t setting=NULL;
 304   int found = 0;
 305
 306   if (!xbt_log_settings)
 307     return;
 308
 309   xbt_assert0(cat,"NULL category");
 310   xbt_assert(cat->name);
 311
 312   xbt_dynar_foreach(xbt_log_settings,cursor,setting) {
 313     xbt_assert0(setting,"Damnit, NULL cat in the list");
 314     xbt_assert1(setting->catname,"NULL setting(=%p)->catname",(void*)setting);
 315
 316     if (!strcmp(setting->catname,cat->name)) {
 317       found = 1;
 318
 319       xbt_log_threshold_set(cat, setting->thresh);
 320       xbt_dynar_cursor_rm(xbt_log_settings,&cursor);
 321
 322       if (cat->threshold <= xbt_log_priority_verbose) {
 323         s_xbt_log_event_t _log_ev =
 324           {cat,xbt_log_priority_verbose,__FILE__,_XBT_GNUC_FUNCTION,__LINE__};
 325         _xbt_log_event_log(&_log_ev,
 326                  "Apply settings for category '%s': set threshold to %s (=%d)",
 327                  cat->name,
 328                  xbt_log_priority_names[cat->threshold], cat->threshold);
 329       }
 330     }
 331   }
 332   if (!found && cat->threshold <= xbt_log_priority_verbose) {
 333     s_xbt_log_event_t _log_ev =
 334       {cat,xbt_log_priority_verbose,__FILE__,_XBT_GNUC_FUNCTION,__LINE__};
 335     _xbt_log_event_log(&_log_ev,
 336                         "Category '%s': inherited threshold = %s (=%d)",
 337                         cat->name,
 338                         xbt_log_priority_names[cat->threshold], cat->threshold);
 339   }
 340
 341 }
 342
 343 void _xbt_log_event_log( xbt_log_event_t ev, const char *fmt, ...) {
 344   xbt_log_category_t cat = ev->cat;
 345   va_start(ev->ap, fmt);
 346   while(1) {
 347     xbt_log_appender_t appender = cat->appender;
 348     if (appender != NULL) {
 349       appender->do_append(appender, ev, fmt);
 350     }
 351     if (!cat->willLogToParent)
 352       break;
 353
 354     cat = cat->parent;
 355   }
 356   va_end(ev->ap);
 357 }
 358
 359 static void _cat_init(xbt_log_category_t category) {
 360   if (category == &_XBT_LOGV(XBT_LOG_ROOT_CAT)) {
 361     category->threshold = xbt_log_priority_info;
 362     category->appender = xbt_log_default_appender;
 363   } else {
 364     xbt_log_parent_set(category, category->parent);
 365   }
 366   _apply_control(category);
 367 }
 368
 369 /*
 370  * This gets called the first time a category is referenced and performs the
 371  * initialization.
 372  * Also resets threshold to inherited!
 373  */
 374 int _xbt_log_cat_init(e_xbt_log_priority_t priority,
 375                        xbt_log_category_t   category) {
 376
 377   _cat_init(category);
 378
 379   return priority >= category->threshold;
 380 }
 381
 382 void xbt_log_parent_set(xbt_log_category_t cat,
 383                          xbt_log_category_t parent) {
 384
 385   xbt_assert0(cat,"NULL category to be given a parent");
 386   xbt_assert1(parent,"The parent category of %s is NULL",cat->name);
 387
 388   /* unlink from current parent */
 389   if (cat->threshold != xbt_log_priority_uninitialized) {
 390     xbt_log_category_t* cpp = &parent->firstChild;
 391     while(*cpp != cat && *cpp != NULL) {
 392       cpp = &(*cpp)->nextSibling;
 393     }
 394     xbt_assert(*cpp == cat);
 395     *cpp = cat->nextSibling;
 396   }
 397
 398   /* Set new parent */
 399   cat->parent = parent;
 400   cat->nextSibling = parent->firstChild;
 401   parent->firstChild = cat;
 402
 403   /* Make sure parent is initialized */
 404   if (parent->threshold == xbt_log_priority_uninitialized) {
 405     _cat_init(parent);
 406   }
 407
 408   /* Reset priority */
 409   cat->threshold = parent->threshold;
 410   cat->isThreshInherited = 1;
 411 } /* log_setParent */
 412
 413 static void _set_inherited_thresholds(xbt_log_category_t cat) {
 414   xbt_log_category_t child = cat->firstChild;
 415   for( ; child != NULL; child = child->nextSibling) {
 416     if (child->isThreshInherited) {
 417       if (cat != &_XBT_LOGV(log))
 418         VERB3("Set category threshold of %s to %s (=%d)",
 419               child->name,xbt_log_priority_names[cat->threshold],cat->threshold);
 420       child->threshold = cat->threshold;
 421       _set_inherited_thresholds(child);
 422     }
 423   }
 424 }
 425
 426 void xbt_log_threshold_set(xbt_log_category_t   cat,
 427                             e_xbt_log_priority_t threshold) {
 428   cat->threshold = threshold;
 429   cat->isThreshInherited = 0;
 430   _set_inherited_thresholds(cat);
 431 }
 432
 433 static void _xbt_log_parse_setting(const char*        control_string,
 434                                     xbt_log_setting_t set) {
 435   const char *name, *dot, *eq;
 436
 437   set->catname=NULL;
 438   if (!*control_string)
 439     return;
 440   DEBUG1("Parse log setting '%s'",control_string);
 441
 442   control_string += strspn(control_string, " ");
 443   name = control_string;
 444   control_string += strcspn(control_string, ".= ");
 445   dot = control_string;
 446   control_string += strcspn(control_string, "= ");
 447   eq = control_string;
 448   control_string += strcspn(control_string, " ");
 449
 450   xbt_assert1(*dot == '.' && *eq == '=',
 451                "Invalid control string '%s'",control_string);
 452
 453   if (!strncmp(dot + 1, "thresh", min(eq - dot - 1,strlen("thresh")))) {
 454     int i;
 455     char *neweq=xbt_strdup(eq+1);
 456     char *p=neweq-1;
 457
 458     while (*(++p) != '\0') {
 459       if (*p >= 'a' && *p <= 'z') {
 460         *p-='a'-'A';
 461       }
 462     }
 463
 464     DEBUG1("New priority name = %s",neweq);
 465     for (i=0; i<xbt_log_priority_infinite-1; i++) {
 466       if (!strncmp(xbt_log_priority_names[i],neweq,p-eq)) {
 467         DEBUG1("This is priority %d",i);
 468         break;
 469       }
 470     }
 471     if (i<xbt_log_priority_infinite-1) {
 472       set->thresh=i;
 473     } else {
 474       xbt_assert1(FALSE,"Unknown priority name: %s",eq+1);
 475     }
 476     free(neweq);
 477   } else {
 478     char buff[512];
 479     snprintf(buff,min(512,eq - dot - 1),"%s",dot+1);
 480     xbt_assert1(FALSE,"Unknown setting of the log category: %s",buff);
 481   }
 482   set->catname=(char*)xbt_malloc(dot - name+1);
 483
 484   strncpy(set->catname,name,dot-name);
 485   set->catname[dot-name]='\0'; /* Just in case */
 486   DEBUG1("This is for cat '%s'", set->catname);
 487 }
 488
 489 static xbt_error_t _xbt_log_cat_searchsub(xbt_log_category_t cat,char *name,
 490                                             /*OUT*/xbt_log_category_t*whereto) {
 491   xbt_error_t errcode;
 492   xbt_log_category_t child;
 493
 494   if (!strcmp(cat->name,name)) {
 495     *whereto=cat;
 496     return no_error;
 497   }
 498   for(child=cat->firstChild ; child != NULL; child = child->nextSibling) {
 499     errcode=_xbt_log_cat_searchsub(child,name,whereto);
 500     if (errcode==no_error)
 501       return no_error;
 502   }
 503   return mismatch_error;
 504 }
 505
 506 static void _cleanup_double_spaces(char *s) {
 507   char *p = s;
 508   int   e = 0;
 509
 510   while (1) {
 511     if (!*p)
 512       goto end;
 513
 514     if (!isspace(*p))
 515       break;
 516
 517     p++;
 518   }
 519
 520   e = 1;
 521
 522   do {
 523     if (e)
 524       *s++ = *p;
 525
 526     if (!*++p)
 527       goto end;
 528
 529     if (e ^ !isspace(*p))
 530       if ((e = !e))
 531         *s++ = ' ';
 532   } while (1);
 533
 534  end:
 535   *s = '\0';
 536 }
 537
 538 /**
 539  * \ingroup XBT_log
 540  * \param control_string What to parse
 541  *
 542  * Typically passed a command-line argument. The string has the syntax:
 543  *
 544  *      ( [category] "." [keyword] "=" value (" ")... )...
 545  *
 546  * where [category] is one the category names and keyword is one of the
 547  * following:
 548  *
 549  *      thresh          value is an integer priority level. Sets the category's
 550  *                        threshold priority.
 551  *
 552  * \warning
 553  * This routine may only be called once and that must be before any other
 554  * logging command! Typically, this is done from main().
 555  */
 556 void xbt_log_control_set(const char* control_string) {
 557   xbt_error_t errcode;
 558   xbt_log_setting_t set;
 559   char *cs;
 560   char *p;
 561   int done = 0;
 562
 563   DEBUG1("Parse log settings '%s'",control_string);
 564   if (control_string == NULL)
 565     return;
 566   if (xbt_log_settings == NULL)
 567     xbt_log_settings = xbt_dynar_new(sizeof(xbt_log_setting_t),
 568                                        _free_setting);
 569
 570   set = xbt_new(s_xbt_log_setting_t,1);
 571   cs=xbt_strdup(control_string);
 572
 573   _cleanup_double_spaces(cs);
 574
 575   while (!done) {
 576     xbt_log_category_t cat;
 577
 578     p=strrchr(cs,' ');
 579     if (p) {
 580       *p='\0';
 581       *p++;
 582     } else {
 583       p=cs;
 584       done = 1;
 585     }
 586     _xbt_log_parse_setting(p,set);
 587
 588     errcode = _xbt_log_cat_searchsub(&_XBT_LOGV(root),set->catname,&cat);
 589     if (errcode == mismatch_error) {
 590       DEBUG0("Store for further application");
 591       DEBUG1("push %p to the settings",(void*)set);
 592       xbt_dynar_push(xbt_log_settings,&set);
 593       /* malloc in advance the next slot */
 594       set = xbt_new(s_xbt_log_setting_t,1);
 595     } else {
 596       DEBUG0("Apply directly");
 597       free(set->catname);
 598       xbt_log_threshold_set(cat,set->thresh);
 599     }
 600   }
 601   free(set);
 602   free(cs);
 603 }
 604
 605 void xbt_log_appender_set(xbt_log_category_t cat, xbt_log_appender_t app) {
 606   cat->appender = app;
 607 }
 608