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