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
  22 /*
  23 FAIRE DES ZOLIS LOGS
  24 --------------------
  25 Dans gras, tu ne te contente pas d'écrire des choses à l'écran, mais tu
  26 écris sur un sujet particulier (notion de canal) des choses d'une gravité
  27 particulière. Il y a 7 niveaux de gravité.
  28  trace: tracer les entrées dans une fonction, retour de fonction
  29         (famille de macros XBT_IN/XBT_OUT)
  30  debug: pour t'aider à mettre au point le module, potentiellement tres bavard
  31  verbose: quelques infos succintes sur les internals du module
  32  info: niveau normal, ton de la conversation
  33  warning: problème potentiel, mais auquel on a su faire face
  34  error: problème qui t'as empêché de faire ton job
  35  critical: juste avant de mourir
  36
  37 Quand on compile avec -DNDEBUG (par défaut dans le paquet Debian), tout ce
  38 qui est '>= verbose' est supprimé au moment de la compilation. Retiré du
  39 binaire, killé.
  40
  41 Ensuite, tu écris dans un canal particulier. Tous les canaux sont rangés en
  42 arbre. Il faudrait faire un ptit script qui fouille les sources à la
  43 recherche des macros XBT_LOG_NEW_* utilisées pour créer des canaux. Le
  44 dernier argument de ces macros est ignoré dans le source. Il est destiné à
  45 être la documentation de la chose en une ligne. En gros, ca fait:
  46 root
  47  +--xbt
  48  |   +--config
  49  |   +--dict
  50  |   |   +--dict_cursor
  51  |   |   +--dict_elm
  52  |   |   ...
  53  |   +--dynar
  54  |   +--set
  55  |   +--log
  56  |   +--module
  57  +--gras
  58      +--datadesc
  59      |   +--ddt_cbps
  60      |   +--ddt_convert
  61      |   +--ddt_exchange
  62      |   +--ddt_parse
  63      |       +--lexer
  64      +--msg
  65      +--transport
  66          +--raw_trp (Je devrais tuer ce module, un jour)
  67          +--trp_buf
  68          +--trp_sg
  69          +--trp_file
  70          +--trp_tcp
  71
  72 Et ensuite les utilisateurs peuvent choisir le niveau de gravité qui les
  73 interresse sur tel ou tel sujet.
  74
  75 Toute la mécanique de logging repose sur des variables statiques dont le nom
  76 dépend du nom du canal.
  77  => attention aux conflits de nom de canal
  78  => il faut une macro XBT_LOG dans chaque fichier où tu fais des logs.
  79
  80 XBT_LOG_NEW_CATEGORY: nouveau canal sous "root". Rare, donc.
  81 XBT_LOG_NEW_SUBCATEGORY: nouveau canal dont on précise le père.
  82 XBT_LOG_DEFAULT_CATEGORY: indique quel est le canal par défaut dans ce fichier
  83 XBT_LOG_NEW_DEFAULT_CATEGORY: Crèe un canal et l'utilise par défaut
  84 XBT_LOG_NEW_DEFAULT_SUBCATEGORY: devine
  85 XBT_LOG_EXTERNAL_CATEGORY: quand tu veux utiliser par défaut un canal créé
  86                            dans un autre fichier.
  87
  88 Une fois que ton canal est créé, tu l'utilise avec les macros LOG, DEBUG,
  89 VERB, WARN, ERROR et CRITICAL. Il faut que tu donne le nombre d'arguments
  90 après le nom de macro. Exemple: LOG2("My name is %s %s","Martin","Quinson")
  91 Si tu veux préciser explicitement le canal où écrire, ajoute un C devant le
  92 nom de la macro. Exemple: CCRITICAL0(module, "Cannot initialize GRAS")
  93
  94 Toutes ces macros (enfin, ce en quoi elles se réécrivent) vérifient leurs
  95 arguments comme printf le fait lorsqu'on compile avec gcc.
  96 LOG1("name: %d","toto"); donne un warning, et donc une erreur en mode
  97 mainteneur.
  98
  99 Enfin, tu peux tester si un canal est ouvert à une priorité donnée (pour
 100 préparer plus de débug, par exemple. Dans le parseur, je fais du pretty
 101 printing sur ce qu'il faut parser dans ce cas).
 102 XBT_LOG_ISENABLED(catName, priority) Le second argument doit être une valeur
 103 de e_xbt_log_priority_t (log.h). Par exemple: xbt_log_priority_verbose
 104
 105 Voila sur comment mettre des logs dans ton code. N'hesite pas à faire pleins
 106 de canaux différents pour des aspects différents de ton code. En
 107 particulier, dans les dict, j'ai un canal pour l'ajout, le retrait, le
 108 netoyage du code après suppression et ainsi de suite. De cette façon, je
 109 peux choisir qui m'interresse.
 110
 111
 112 Pour utiliser les logs, tu déjà faire, non ? Tu colle sur la ligne de
 113 commande un ou plusieurs arguments de la forme
 114   --gras-log="<réglage> [<reglage>+]" (ou sans " si t'as pas d'espace)
 115 chaque réglage étant de la forme:
 116   <canal>.thres=<priorité>
 117 Les différents réglages sont lus de gauche à droite.
 118 "root.thres=debug root.thres=critical" ferme tout, normalement.
 119
 120 */
 121
 122 typedef struct {
 123   char *catname;
 124   e_xbt_log_priority_t thresh;
 125 } s_xbt_log_setting_t,*xbt_log_setting_t;
 126
 127 static xbt_dynar_t xbt_log_settings=NULL;
 128 static void _free_setting(void *s) {
 129   xbt_log_setting_t set=(xbt_log_setting_t)s;
 130   if (set) {
 131     xbt_free(set->catname);
 132 /*    xbt_free(set); FIXME: uncommenting this leads to segfault when more than one chunk is passed as gras-log */
 133   }
 134 }
 135
 136 const char *xbt_log_priority_names[8] = {
 137   "NONE",
 138   "TRACE",
 139   "DEBUG",
 140   "VERBOSE",
 141   "INFO",
 142   "WARNING",
 143   "ERROR",
 144   "CRITICAL"
 145 };
 146
 147 s_xbt_log_category_t _XBT_LOGV(XBT_LOG_ROOT_CAT) = {
 148   0, 0, 0,
 149   "root", xbt_log_priority_uninitialized, 0,
 150   NULL, 0
 151 };
 152
 153 XBT_LOG_NEW_SUBCATEGORY(xbt,XBT_LOG_ROOT_CAT,"All XBT categories (simgrid toolbox)");
 154 XBT_LOG_NEW_SUBCATEGORY(surf,XBT_LOG_ROOT_CAT,"All SURF categories");
 155 XBT_LOG_NEW_DEFAULT_SUBCATEGORY(log,xbt,"Loggings from the logging mecanism itself");
 156
 157 void xbt_log_init(int *argc,char **argv, const char *defaultlog) {
 158   int i,j;
 159   char *opt;
 160   int found=0;
 161
 162   /** Set logs and init log submodule */
 163   for (i=1; i<*argc; i++) {
 164     if (!strncmp(argv[i],"--gras-log=",strlen("--gras-log=")) ||
 165         !strncmp(argv[i],"--surf-log=",strlen("--surf-log=")) ||
 166         !strncmp(argv[i],"--msg-log=",strlen("--msg-log=")) ||
 167         !strncmp(argv[i],"--xbt-log=",strlen("--xbt-log="))) {
 168       found = 1;
 169       opt=strchr(argv[i],'=');
 170       opt++;
 171       xbt_log_control_set(opt);
 172       DEBUG1("Did apply '%s' as log setting",opt);
 173       /*remove this from argv*/
 174       for (j=i+1; j<*argc; j++) {
 175         argv[j-1] = argv[j];
 176       }
 177       argv[j-1] = NULL;
 178       (*argc)--;
 179       i--; /* compensate effect of next loop incrementation */
 180     }
 181   }
 182   if (!found && defaultlog) {
 183      xbt_log_control_set(defaultlog);
 184   }
 185 }
 186
 187 void xbt_log_exit(void) {
 188   VERB0("Exiting log");
 189   xbt_dynar_free(&xbt_log_settings);
 190   VERB0("Exited log");
 191 }
 192
 193 static void _apply_control(xbt_log_category_t cat) {
 194   int cursor;
 195   xbt_log_setting_t setting=NULL;
 196   int found = 0;
 197
 198   if (!xbt_log_settings)
 199     return;
 200
 201   xbt_assert0(cat,"NULL category");
 202   xbt_assert(cat->name);
 203
 204   xbt_dynar_foreach(xbt_log_settings,cursor,setting) {
 205     xbt_assert0(setting,"Damnit, NULL cat in the list");
 206     xbt_assert1(setting->catname,"NULL setting(=%p)->catname",(void*)setting);
 207
 208     if (!strcmp(setting->catname,cat->name)) {
 209       found = 1;
 210
 211       xbt_log_threshold_set(cat, setting->thresh);
 212       xbt_dynar_cursor_rm(xbt_log_settings,&cursor);
 213
 214       if (cat->threshold <= xbt_log_priority_verbose) {
 215         s_xbt_log_event_t _log_ev =
 216           {cat,xbt_log_priority_verbose,__FILE__,_XBT_GNUC_FUNCTION,__LINE__};
 217         _xbt_log_event_log(&_log_ev,
 218                  "Apply settings for category '%s': set threshold to %s (=%d)",
 219                  cat->name,
 220                  xbt_log_priority_names[cat->threshold], cat->threshold);
 221       }
 222     }
 223   }
 224   if (!found && cat->threshold <= xbt_log_priority_verbose) {
 225     s_xbt_log_event_t _log_ev =
 226       {cat,xbt_log_priority_verbose,__FILE__,_XBT_GNUC_FUNCTION,__LINE__};
 227     _xbt_log_event_log(&_log_ev,
 228                         "Category '%s': inherited threshold = %s (=%d)",
 229                         cat->name,
 230                         xbt_log_priority_names[cat->threshold], cat->threshold);
 231   }
 232
 233 }
 234
 235 void _xbt_log_event_log( xbt_log_event_t ev, const char *fmt, ...) {
 236   xbt_log_category_t cat = ev->cat;
 237   va_start(ev->ap, fmt);
 238   while(1) {
 239     xbt_log_appender_t appender = cat->appender;
 240     if (appender != NULL) {
 241       appender->do_append(appender, ev, fmt);
 242     }
 243     if (!cat->willLogToParent)
 244       break;
 245
 246     cat = cat->parent;
 247   }
 248   va_end(ev->ap);
 249 }
 250
 251 static void _cat_init(xbt_log_category_t category) {
 252   if (category == &_XBT_LOGV(XBT_LOG_ROOT_CAT)) {
 253     category->threshold = xbt_log_priority_info;
 254     category->appender = xbt_log_default_appender;
 255   } else {
 256     xbt_log_parent_set(category, category->parent);
 257   }
 258   _apply_control(category);
 259 }
 260
 261 /*
 262  * This gets called the first time a category is referenced and performs the
 263  * initialization.
 264  * Also resets threshold to inherited!
 265  */
 266 int _xbt_log_cat_init(e_xbt_log_priority_t priority,
 267                        xbt_log_category_t   category) {
 268
 269   _cat_init(category);
 270
 271   return priority >= category->threshold;
 272 }
 273
 274 void xbt_log_parent_set(xbt_log_category_t cat,
 275                          xbt_log_category_t parent) {
 276
 277   xbt_assert0(cat,"NULL category to be given a parent");
 278   xbt_assert1(parent,"The parent category of %s is NULL",cat->name);
 279
 280   /* unlink from current parent */
 281   if (cat->threshold != xbt_log_priority_uninitialized) {
 282     xbt_log_category_t* cpp = &parent->firstChild;
 283     while(*cpp != cat && *cpp != NULL) {
 284       cpp = &(*cpp)->nextSibling;
 285     }
 286     xbt_assert(*cpp == cat);
 287     *cpp = cat->nextSibling;
 288   }
 289
 290   /* Set new parent */
 291   cat->parent = parent;
 292   cat->nextSibling = parent->firstChild;
 293   parent->firstChild = cat;
 294
 295   /* Make sure parent is initialized */
 296   if (parent->threshold == xbt_log_priority_uninitialized) {
 297     _cat_init(parent);
 298   }
 299
 300   /* Reset priority */
 301   cat->threshold = parent->threshold;
 302   cat->isThreshInherited = 1;
 303 } /* log_setParent */
 304
 305 static void _set_inherited_thresholds(xbt_log_category_t cat) {
 306   xbt_log_category_t child = cat->firstChild;
 307   for( ; child != NULL; child = child->nextSibling) {
 308     if (child->isThreshInherited) {
 309       if (cat != &_XBT_LOGV(log))
 310         VERB3("Set category threshold of %s to %s (=%d)",
 311               child->name,xbt_log_priority_names[cat->threshold],cat->threshold);
 312       child->threshold = cat->threshold;
 313       _set_inherited_thresholds(child);
 314     }
 315   }
 316 }
 317
 318 void xbt_log_threshold_set(xbt_log_category_t   cat,
 319                             e_xbt_log_priority_t threshold) {
 320   cat->threshold = threshold;
 321   cat->isThreshInherited = 0;
 322   _set_inherited_thresholds(cat);
 323 }
 324
 325 static void _xbt_log_parse_setting(const char*        control_string,
 326                                     xbt_log_setting_t set) {
 327   const char *name, *dot, *eq;
 328
 329   set->catname=NULL;
 330   if (!*control_string)
 331     return;
 332   DEBUG1("Parse log setting '%s'",control_string);
 333
 334   control_string += strspn(control_string, " ");
 335   name = control_string;
 336   control_string += strcspn(control_string, ".= ");
 337   dot = control_string;
 338   control_string += strcspn(control_string, "= ");
 339   eq = control_string;
 340   control_string += strcspn(control_string, " ");
 341
 342   xbt_assert1(*dot == '.' && *eq == '=',
 343                "Invalid control string '%s'",control_string);
 344
 345   if (!strncmp(dot + 1, "thresh", min(eq - dot - 1,strlen("thresh")))) {
 346     int i;
 347     char *neweq=xbt_strdup(eq+1);
 348     char *p=neweq-1;
 349
 350     while (*(++p) != '\0') {
 351       if (*p >= 'a' && *p <= 'z') {
 352         *p-='a'-'A';
 353       }
 354     }
 355
 356     DEBUG1("New priority name = %s",neweq);
 357     for (i=0; i<xbt_log_priority_infinite-1; i++) {
 358       if (!strncmp(xbt_log_priority_names[i],neweq,p-eq)) {
 359         DEBUG1("This is priority %d",i);
 360         break;
 361       }
 362     }
 363     if (i<xbt_log_priority_infinite-1) {
 364       set->thresh=i;
 365     } else {
 366       xbt_assert1(FALSE,"Unknown priority name: %s",eq+1);
 367     }
 368     xbt_free(neweq);
 369   } else {
 370     char buff[512];
 371     snprintf(buff,min(512,eq - dot - 1),"%s",dot+1);
 372     xbt_assert1(FALSE,"Unknown setting of the log category: %s",buff);
 373   }
 374   set->catname=(char*)xbt_malloc(dot - name+1);
 375
 376   strncpy(set->catname,name,dot-name);
 377   set->catname[dot-name]='\0'; /* Just in case */
 378   DEBUG1("This is for cat '%s'", set->catname);
 379 }
 380
 381 static xbt_error_t _xbt_log_cat_searchsub(xbt_log_category_t cat,char *name,
 382                                             /*OUT*/xbt_log_category_t*whereto) {
 383   xbt_error_t errcode;
 384   xbt_log_category_t child;
 385
 386   if (!strcmp(cat->name,name)) {
 387     *whereto=cat;
 388     return no_error;
 389   }
 390   for(child=cat->firstChild ; child != NULL; child = child->nextSibling) {
 391     errcode=_xbt_log_cat_searchsub(child,name,whereto);
 392     if (errcode==no_error)
 393       return no_error;
 394   }
 395   return mismatch_error;
 396 }
 397
 398 static void _cleanup_double_spaces(char *s) {
 399   char *p = s;
 400   int   e = 0;
 401
 402   while (1) {
 403     if (!*p)
 404       goto end;
 405
 406     if (!isspace(*p))
 407       break;
 408
 409     p++;
 410   }
 411
 412   e = 1;
 413
 414   do {
 415     if (e)
 416       *s++ = *p;
 417
 418     if (!*++p)
 419       goto end;
 420
 421     if (e ^ !isspace(*p))
 422       if ((e = !e))
 423         *s++ = ' ';
 424   } while (1);
 425
 426  end:
 427   *s = '\0';
 428 }
 429
 430 /**
 431  * \ingroup XBT_log
 432  * \param control_string What to parse
 433  *
 434  * Typically passed a command-line argument. The string has the syntax:
 435  *
 436  *      ( [category] "." [keyword] "=" value (" ")... )...
 437  *
 438  * where [category] is one the category names and keyword is one of the
 439  * following:
 440  *
 441  *      thresh          value is an integer priority level. Sets the category's
 442  *                        threshold priority.
 443  *
 444  * \warning
 445  * This routine may only be called once and that must be before any other
 446  * logging command! Typically, this is done from main().
 447  */
 448 void xbt_log_control_set(const char* control_string) {
 449   xbt_error_t errcode;
 450   xbt_log_setting_t set;
 451   char *cs;
 452   char *p;
 453   int done = 0;
 454
 455   DEBUG1("Parse log settings '%s'",control_string);
 456   if (control_string == NULL)
 457     return;
 458   if (xbt_log_settings == NULL)
 459     xbt_log_settings = xbt_dynar_new(sizeof(xbt_log_setting_t),
 460                                        _free_setting);
 461
 462   set = xbt_new(s_xbt_log_setting_t,1);
 463   cs=xbt_strdup(control_string);
 464
 465   _cleanup_double_spaces(cs);
 466
 467   while (!done) {
 468     xbt_log_category_t cat;
 469
 470     p=strrchr(cs,' ');
 471     if (p) {
 472       *p='\0';
 473       *p++;
 474     } else {
 475       p=cs;
 476       done = 1;
 477     }
 478     _xbt_log_parse_setting(p,set);
 479
 480     errcode = _xbt_log_cat_searchsub(&_XBT_LOGV(root),set->catname,&cat);
 481     if (errcode == mismatch_error) {
 482       DEBUG0("Store for further application");
 483       DEBUG1("push %p to the settings",(void*)set);
 484       xbt_dynar_push(xbt_log_settings,&set);
 485       /* malloc in advance the next slot */
 486       set = xbt_new(s_xbt_log_setting_t,1);
 487     } else {
 488       DEBUG0("Apply directly");
 489       xbt_free(set->catname);
 490       xbt_log_threshold_set(cat,set->thresh);
 491     }
 492   }
 493   xbt_free(set);
 494   xbt_free(cs);
 495 }
 496
 497 void xbt_log_appender_set(xbt_log_category_t cat, xbt_log_appender_t app) {
 498   cat->appender = app;
 499 }
 500