3 /* log - a generic logging facility in the spirit of log4j */
5 /* Copyright (c) 2003, 2004 Martin Quinson. All rights reserved. */
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. */
13 #include <stdio.h> /* snprintf */
14 #include <stdlib.h> /* snprintf */
16 #include "portable.h" /* to get a working stdarg.h */
18 #include "xbt_modinter.h"
22 #include "xbt/sysdep.h"
24 #include "xbt/dynar.h"
26 /** \addtogroup XBT_log
28 * This section describes the API to the log functions used
29 * everywhere in this project.
31 \section XBT_log_toc Table of contents
43 - \ref log_API_example
52 \section log_overview 1. Introduction
54 This module is in charge of handling the log messages of every SimGrid
55 program. The main design goal are:
57 - <b>configurability</b>: the user can choose <i>at runtime</i> what messages to show and
58 what to hide, as well as how messages get displayed.
59 - <b>ease of use</b>: both to the programmer (using preprocessor macros black magic)
60 and to the user (with command line options)
61 - <b>performances</b>: logging shouldn't slow down the program when turned off, for example
62 - deal with <b>distributed settings</b>: SimGrid programs are [often] distributed ones,
63 and the logging mecanism allows to syndicate each and every log source into the same place.
64 At least, its design would allow to, once we write the last missing pieces
66 There is three main concepts in SimGrid's logging mecanism: <i>category</i>,
67 <i>priority</i> and <i>appender</i>. These three concepts work together to
68 enable developers to log messages according to message type and priority, and
69 to control at runtime how these messages are formatted and where they are
72 \subsection log_cat 1.1 Category hierarchy
74 The first and foremost advantage of any logging API over plain printf()
75 resides in its ability to disable certain log statements while allowing
76 others to print unhindered. This capability assumes that the logging space,
77 that is, the space of all possible logging statements, is categorized
78 according to some developer-chosen criteria.
80 This observation led to choosing category as the central concept of the
81 system. In a certain sense, they can be considered as logging topics or
84 \subsection log_pri 1.2 Logging priorities
86 The user can naturally declare interest into this or that logging category, but
87 he also can specify the desired level of details for each of them. This is
88 controled by the <i>priority</i> concept (which should maybe be renamed to
91 Empirically, the user can specify that he wants to see every debuging message
92 of GRAS while only being interested into the messages at level "error" or
93 higher about the XBT internals.
95 \subsection log_app 1.3 Message appenders
97 The message appenders are the elements in charge of actually displaying the
98 message to the user. For now, there is only one appender: the one able to print
99 stuff on stderr. But everything is in place internally to write new ones, such
100 as the one able to send the strings to a central server in charge of
101 syndicating the logs of every distributed daemons on a well known location.
103 It should also be possible to pass configuration informations to the appenders,
104 specifying for example that the message location (file and line number) is only
105 relevant to debugging information, not to critical error messages.
109 \subsection log_hist 1.4 History of this module
111 Historically, this module is an adaptation of the log4c project, which is dead
112 upstream, and which I was given the permission to fork under the LGPL licence
113 by the log4c's authors. The log4c project itself was loosely based on the
114 Apache project's Log4J, which also inspired Log4CC, Log4py and so on. Our work
115 differs somehow from these projects anyway, because the C programming language
116 is not object oriented.
118 \section log_API 2. Programmer interface
120 \subsection log_API_cat 2.1 Constructing the category hierarchy
122 Every category is declared by providing a name and an optional
123 parent. If no parent is explicitly named, the root category, LOG_ROOT_CAT is
124 the category's parent.
126 A category is created by a macro call at the top level of a file. A
127 category can be created with any one of the following macros:
129 - \ref XBT_LOG_NEW_CATEGORY(MyCat,desc); Create a new root
130 - \ref XBT_LOG_NEW_SUBCATEGORY(MyCat, ParentCat,desc);
131 Create a new category being child of the category ParentCat
132 - \ref XBT_LOG_NEW_DEFAULT_CATEGORY(MyCat,desc);
133 Like XBT_LOG_NEW_CATEGORY, but the new category is the default one
135 - \ref XBT_LOG_NEW_DEFAULT_SUBCATEGORY(MyCat, ParentCat,desc);
136 Like XBT_LOG_NEW_SUBCATEGORY, but the new category is the default one
139 The parent cat can be defined in the same file or in another file (in
140 which case you want to use the \ref XBT_LOG_EXTERNAL_CATEGORY macro to make
141 it visible in the current file), but each category may have only one
144 Typically, there will be a Category for each module and sub-module, so you
145 can independently control logging for each module.
147 For a list of all existing categories, please refer to the \ref XBT_log_cats
148 section. This file is generated automatically from the SimGrid source code, so
149 it should be complete and accurate.
151 \section log_API_pri 2.2 Declaring message priority
153 A category may be assigned a threshold priorty. The set of priorites are
154 defined by the \ref e_xbt_log_priority_t enum. All logging request under
155 this priority will be discarded.
157 If a given category is not assigned a threshold priority, then it inherits
158 one from its closest ancestor with an assigned threshold. To ensure that all
159 categories can eventually inherit a threshold, the root category always has
160 an assigned threshold priority.
162 Logging requests are made by invoking a logging macro on a category. All of
163 the macros have a printf-style format string followed by arguments. If you
164 compile with the -Wall option, gcc will warn you for unmatched arguments, ie
165 when you pass a pointer to a string where an integer was specified by the
166 format. This is usualy a good idea.
168 Because some C compilers do not support vararg macros, there is a version of
169 the macro for any number of arguments from 0 to 6. The macro name ends with
170 the total number of arguments.
172 Here is an example of the most basic type of macro. This is a logging
173 request with priority <i>warning</i>.
175 <code>CLOG5(MyCat, gras_log_priority_warning, "Values are: %d and '%s'", 5,
178 A logging request is said to be enabled if its priority is higher than or
179 equal to the threshold priority of its category. Otherwise, the request is
180 said to be disabled. A category without an assigned priority will inherit
181 one from the hierarchy.
183 It is possible to use any non-negative integer as a priority. If, as in the
184 example, one of the standard priorites is used, then there is a convenience
185 macro that is typically used instead. For example, the above example is
186 equivalent to the shorter:
188 <code>CWARN4(MyCat, "Values are: %d and '%s'", 5, "oops");</code>
190 \section log_API_subcat 2.3 Using a default category (the easy interface)
192 If \ref XBT_LOG_NEW_DEFAULT_SUBCATEGORY(MyCat, Parent) or
193 \ref XBT_LOG_NEW_DEFAULT_CATEGORY(MyCat) is used to create the
194 category, then the even shorter form can be used:
196 <code>WARN3("Values are: %d and '%s'", 5, "oops");</code>
198 Only one default category can be created per file, though multiple
199 non-defaults can be created and used.
201 \section log_API_easy 2.4 Putting all together: the easy interface
203 First of all, each module should register its own category into the categories
204 tree using \ref XBT_LOG_NEW_DEFAULT_SUBCATEGORY.
206 Then, logging should be done with the DEBUG<n>, VERB<n>, INFO<n>, WARN<n>,
207 ERROR<n> or CRITICAL<n> macro families (such as #DEBUG10, #VERB6,
208 #INFO8, #WARN6, #ERROR6 and #CRITICAL6). For each group, there is at
209 least 6 different macros (like DEBUG0, DEBUG1, DEBUG2, DEBUG3, DEBUG4 and
210 DEBUG5), only differing in the number of arguments passed along the format.
211 This is because we want SimGrid itself to keep compilable on ancient
212 compiler not supporting variable number of arguments to macros. But we
213 should provide a macro simpler to use for the users not interested in SP3
216 Under GCC, these macro check there arguments the same way than printf does. So,
217 if you compile with -Wall, the folliwing code will issue a warning:
218 <code>DEBUG2("Found %s (id %f)", some_string, a_double)</code>
220 If you want to specify the category to log onto (for example because you
221 have more than one category per file, add a C before the name of the log
222 producing macro (ie, use #CDEBUG10, #CVERB6, #CINFO8, #CWARN6, #CERROR6 and
223 #CCRITICAL6 and friends), and pass the category name as first argument.
225 The TRACE priority is not used the same way than the other. You should use
226 the #XBT_IN, XBT_IN<n> (up to #XBT_IN5), #XBT_OUT and #XBT_HERE macros
229 \section log_API_example 2.5 Example of use
231 Here is a more complete example:
236 / * create a category and a default subcategory * /
237 XBT_LOG_NEW_CATEGORY(VSS);
238 XBT_LOG_NEW_DEFAULT_SUBCATEGORY(SA, VSS);
241 / * Now set the parent's priority. (the string would typcially be a runtime option) * /
242 xbt_log_control_set("SA.thresh:3");
244 / * This request is enabled, because WARNING >= INFO. * /
245 CWARN2(VSS, "Low fuel level.");
247 / * This request is disabled, because DEBUG < INFO. * /
248 CDEBUG2(VSS, "Starting search for nearest gas station.");
250 / * The default category SA inherits its priority from VSS. Thus,
251 the following request is enabled because INFO >= INFO. * /
252 INFO1("Located nearest gas station.");
254 / * This request is disabled, because DEBUG < INFO. * /
255 DEBUG1("Exiting gas station search");
260 \section log_user 3. User interface
262 \section log_use_conf 3.1 Configuration
263 Configuration is typically done during program initialization by invoking
264 the xbt_log_control_set() method. The control string passed to it typically
265 comes from the command line. Look at the documentation for that function for
266 the format of the control string.
268 Any SimGrid program can furthermore be configured at run time by passing a
269 --xbt-log argument on the command line (--gras-log, --msg-log and --surf-log
270 are synonyms provided by aestheticism). You can provide several of those
271 arguments to change the setting of several categories, they will be applied
272 from left to right. So,
273 \verbatim --xbt-log="root.thres:debug root.thres:critical"\endverbatim
274 should disable any logging.
276 Note that the quotes on above line are mandatory because there is a space in
277 the argument, so we are protecting ourselves from the shell, not from SimGrid.
278 We could also reach the same effect with this:
279 \verbatim --xbt-log=root.thres:debug --xbt-log=root.thres:critical\endverbatim
281 \section log_use_misc 3.2 Misc and Caveats
283 - Do not use any of the macros that start with '_'.
284 - Log4J has a 'rolling file appender' which you can select with a run-time
285 option and specify the max file size. This would be a nice default for
286 non-kernel applications.
287 - Careful, category names are global variables.
289 \section log_internals 4. Internal considerations
291 This module is a mess of macro black magic, and when it goes wrong, SimGrid
292 studently loose its ability to explain its problems. When messing around this
293 module, I often find useful to define XBT_LOG_MAYDAY (which turns it back to
294 good old printf) for the time of finding what's going wrong.
296 \section log_in_perf 4.1 Performance
298 Except for the first invocation of a given category, a disabled logging request
299 requires an a single comparison of a static variable to a constant.
301 There is also compile time constant, \ref XBT_LOG_STATIC_THRESHOLD, which
302 causes all logging requests with a lower priority to be optimized to 0 cost
303 by the compiler. By setting it to gras_log_priority_infinite, all logging
304 requests are statically disabled and cost nothing. Released executables
305 might be compiled with
306 \verbatim-DXBT_LOG_STATIC_THRESHOLD=gras_log_priority_infinite\endverbatim
308 Compiling with the \verbatim-DNLOG\endverbatim option disables all logging
309 requests at compilation time while the \verbatim-DNDEBUG\endverbatim disables
310 the requests of priority below INFO.
312 \todo Logging performance *may* be improved further by improving the message
313 propagation from appender to appender in the category tree.
315 \section log_in_app 4.2 Appenders
317 Each category has an optional appender. An appender is a pointer to a
318 structure which starts with a pointer to a doAppend() function. DoAppend()
319 prints a message to a log.
321 When a category is passed a message by one of the logging macros, the
322 category performs the following actions:
324 - if the category has an appender, the message is passed to the
325 appender's doAppend() function,
326 - if additivity is true for the category (which is the case by
327 default, and can be controlled by xbt_log_additivity_set()), the
328 message is passed to the category's parent.
330 By default, only the root category have an appender, and any other category has
331 its additivity set to true. This causes all messages to be logged by the root
334 The default appender function currently prints to stderr, and no other one
335 exist, even if more would be needed, like the one able to send the logs to a
336 remote dedicated server, or other ones offering different output formats.
337 This is on our TODO list for quite a while now, but your help would be
344 xbt_log_appender_t xbt_log_default_appender = NULL; /* set in log_init */
348 e_xbt_log_priority_t thresh;
349 } s_xbt_log_setting_t,*xbt_log_setting_t;
351 static xbt_dynar_t xbt_log_settings=NULL;
353 static void _free_setting(void *s) {
354 xbt_log_setting_t set=*(xbt_log_setting_t*)s;
361 const char *xbt_log_priority_names[8] = {
372 s_xbt_log_category_t XBT_PUBLIC_DATA _XBT_LOGV(XBT_LOG_ROOT_CAT) = {
374 "root", xbt_log_priority_uninitialized, 0,
378 XBT_LOG_NEW_CATEGORY(xbt,"All XBT categories (simgrid toolbox)");
379 XBT_LOG_NEW_CATEGORY(surf,"All SURF categories");
380 XBT_LOG_NEW_CATEGORY(msg,"All MSG categories");
381 XBT_LOG_NEW_CATEGORY(simix,"All SIMIX categories");
382 XBT_LOG_NEW_DEFAULT_SUBCATEGORY(log,xbt,"Loggings from the logging mechanism itself");
384 /** @brief Get all logging settings from the command line
386 * xbt_log_control_set() is called on each string we got from cmd line
388 void xbt_log_init(int *argc,char **argv) {
392 /* create the default appender and install it in the root category,
393 which were already created (damnit. Too slow little beetle)*/
394 xbt_log_default_appender =
395 xbt_log_appender_file_new(xbt_log_layout_simple_new());
396 _XBT_LOGV(XBT_LOG_ROOT_CAT).appender = xbt_log_default_appender;
398 /* Set logs and init log submodule */
399 for (i=1; i<*argc; i++){
400 if (!strncmp(argv[i],"--log=",strlen("--log=")) ||
401 !strncmp(argv[i],"--gras-log=",strlen("--gras-log=")) ||
402 !strncmp(argv[i],"--surf-log=",strlen("--surf-log=")) ||
403 !strncmp(argv[i],"--msg-log=",strlen("--msg-log=")) ||
404 !strncmp(argv[i],"--simix-log=",strlen("--simix-log=")) ||
405 !strncmp(argv[i],"--xbt-log=",strlen("--xbt-log="))){
407 opt=strchr(argv[i],'=');
409 xbt_log_control_set(opt);
410 DEBUG1("Did apply '%s' as log setting",opt);
411 /*remove this from argv*/
413 for (j=i+1; j<*argc; j++){
419 i--; /* compensate effect of next loop incrementation */
424 static void log_shutdown_category(xbt_log_category_t cat) {
425 xbt_log_category_t child;
428 if (cat->appender->layout) {
429 if (cat->appender->layout->free_)
430 cat->appender->layout->free_(cat->appender->layout);
431 free(cat->appender->layout);
433 if (cat->appender->free_)
434 cat->appender->free_(cat->appender);
439 for(child=cat->firstChild ; child != NULL; child = child->nextSibling)
440 log_shutdown_category(child);
443 void xbt_log_exit(void) {
444 VERB0("Exiting log");
445 xbt_dynar_free(&xbt_log_settings);
446 log_shutdown_category(&_XBT_LOGV(XBT_LOG_ROOT_CAT));
450 void _xbt_log_event_log( xbt_log_event_t ev, const char *fmt, ...) {
452 xbt_log_category_t cat = ev->cat;
454 va_start(ev->ap, fmt);
456 xbt_log_appender_t appender = cat->appender;
457 if (appender != NULL) {
459 char *str= appender->layout->do_layout(appender->layout,
461 appender->do_append(appender, str);
463 if (!cat->additivity)
472 * This gets called the first time a category is referenced and performs the
474 * Also resets threshold to inherited!
476 int _xbt_log_cat_init(xbt_log_category_t category,
477 e_xbt_log_priority_t priority) {
479 xbt_log_setting_t setting=NULL;
481 s_xbt_log_event_t _log_ev;
483 if(category == &_XBT_LOGV(XBT_LOG_ROOT_CAT)){
484 category->threshold = xbt_log_priority_info;/* xbt_log_priority_debug*/;
485 category->appender = xbt_log_default_appender;
488 if (!category->parent)
489 category->parent = &_XBT_LOGV(XBT_LOG_ROOT_CAT);
491 xbt_log_parent_set(category, category->parent);
494 /* Apply the control */
495 if (!xbt_log_settings)
496 return priority >= category->threshold;
498 xbt_assert0(category,"NULL category");
499 xbt_assert(category->name);
501 xbt_dynar_foreach(xbt_log_settings,cursor,setting) {
502 xbt_assert0(setting,"Damnit, NULL cat in the list");
503 xbt_assert1(setting->catname,"NULL setting(=%p)->catname",(void*)setting);
505 if (!strcmp(setting->catname,category->name)) {
509 xbt_log_threshold_set(category, setting->thresh);
510 xbt_dynar_cursor_rm(xbt_log_settings,&cursor);
512 if (category->threshold <= xbt_log_priority_debug) {
513 _log_ev.cat = category;
514 _log_ev.priority = xbt_log_priority_debug;
515 _log_ev.fileName = __FILE__ ;
516 _log_ev.functionName = _XBT_FUNCTION ;
517 _log_ev.lineNum = __LINE__ ;
519 _xbt_log_event_log(&_log_ev,
520 "Apply settings for category '%s': set threshold to %s (=%d)",
522 xbt_log_priority_names[category->threshold], category->threshold);
527 if (!found && category->threshold <= xbt_log_priority_verbose) {
529 _log_ev.cat = category;
530 _log_ev.priority = xbt_log_priority_verbose;
531 _log_ev.fileName = __FILE__ ;
532 _log_ev.functionName = _XBT_FUNCTION ;
533 _log_ev.lineNum = __LINE__ ;
535 _xbt_log_event_log(&_log_ev,
536 "Category '%s': inherited threshold = %s (=%d)",
538 xbt_log_priority_names[category->threshold], category->threshold);
541 return priority >= category->threshold;
544 void xbt_log_parent_set(xbt_log_category_t cat,xbt_log_category_t parent)
547 xbt_assert0(cat,"NULL category to be given a parent");
548 xbt_assert1(parent,"The parent category of %s is NULL",cat->name);
551 * if the threshold is initialized
552 * unlink from current parent
554 if(cat->threshold != xbt_log_priority_uninitialized){
556 xbt_log_category_t* cpp = &parent->firstChild;
558 while(*cpp != cat && *cpp != NULL) {
559 cpp = &(*cpp)->nextSibling;
562 xbt_assert(*cpp == cat);
563 *cpp = cat->nextSibling;
566 cat->parent = parent;
567 cat->nextSibling = parent->firstChild;
569 parent->firstChild = cat;
571 if (parent->threshold == xbt_log_priority_uninitialized){
573 _xbt_log_cat_init(parent,
574 xbt_log_priority_uninitialized/* ignored*/);
577 cat->threshold = parent->threshold;
579 cat->isThreshInherited = 1;
583 static void _set_inherited_thresholds(xbt_log_category_t cat) {
586 xbt_log_category_t child = cat->firstChild;
588 for( ; child != NULL; child = child->nextSibling) {
589 if (child->isThreshInherited) {
590 if (cat != &_XBT_LOGV(log))
591 VERB3("Set category threshold of %s to %s (=%d)",
592 child->name,xbt_log_priority_names[cat->threshold],cat->threshold);
593 child->threshold = cat->threshold;
594 _set_inherited_thresholds(child);
601 void xbt_log_threshold_set(xbt_log_category_t cat,
602 e_xbt_log_priority_t threshold) {
603 cat->threshold = threshold;
604 cat->isThreshInherited = 0;
606 _set_inherited_thresholds(cat);
610 static xbt_log_setting_t _xbt_log_parse_setting(const char* control_string) {
612 xbt_log_setting_t set = xbt_new(s_xbt_log_setting_t,1);
613 const char *name, *dot, *eq;
616 if (!*control_string)
618 DEBUG1("Parse log setting '%s'",control_string);
620 control_string += strspn(control_string, " ");
621 name = control_string;
622 control_string += strcspn(control_string, ".= ");
623 dot = control_string;
624 control_string += strcspn(control_string, ":= ");
626 control_string += strcspn(control_string, " ");
628 xbt_assert1(*dot == '.' && (*eq == '=' || *eq == ':'),
629 "Invalid control string '%s'",control_string);
631 if (!strncmp(dot + 1, "thresh", (size_t)(eq - dot - 1))) {
633 char *neweq=xbt_strdup(eq+1);
636 while (*(++p) != '\0') {
637 if (*p >= 'a' && *p <= 'z') {
642 DEBUG1("New priority name = %s",neweq);
643 for (i=0; i<xbt_log_priority_infinite; i++) {
644 if (!strncmp(xbt_log_priority_names[i],neweq,p-eq)) {
645 DEBUG1("This is priority %d",i);
649 if (i<xbt_log_priority_infinite) {
650 set->thresh= (e_xbt_log_priority_t) i;
653 "Unknown priority name: %s (must be one of: trace,debug,verbose,info,warning,error,critical)",eq+1);
658 snprintf(buff,min(512,eq - dot - 1),"%s",dot+1);
659 THROW1(arg_error,0,"Unknown setting of the log category: %s",buff);
661 set->catname=(char*)xbt_malloc(dot - name+1);
663 memcpy(set->catname,name,dot-name);
664 set->catname[dot-name]='\0'; /* Just in case */
665 DEBUG1("This is for cat '%s'", set->catname);
670 static xbt_log_category_t _xbt_log_cat_searchsub(xbt_log_category_t cat,char *name) {
671 xbt_log_category_t child;
673 if (!strcmp(cat->name,name))
676 for(child=cat->firstChild ; child != NULL; child = child->nextSibling)
677 return _xbt_log_cat_searchsub(child,name);
679 THROW1(not_found_error,0,"No such category: %s", name);
684 * \param control_string What to parse
686 * Typically passed a command-line argument. The string has the syntax:
688 * ( [category] "." [keyword] ":" value (" ")... )...
690 * where [category] is one the category names (see \ref XBT_log_cats for a complete list)
691 * and keyword is one of the following:
693 * - thres: category's threshold priority. Possible values:
694 * TRACE,DEBUG,VERBOSE,INFO,WARNING,ERROR,CRITICAL
695 * - add or additivity: whether the logging actions must be passed to
696 * the parent category.
697 * Possible values: 0, 1, yes, no.
698 * Default value: yes.
701 void xbt_log_control_set(const char* control_string) {
702 xbt_log_setting_t set;
704 /* To split the string in commands, and the cursors */
705 xbt_dynar_t set_strings;
711 DEBUG1("Parse log settings '%s'",control_string);
713 /* some initialization if this is the first time that this get called */
714 if (xbt_log_settings == NULL)
715 xbt_log_settings = xbt_dynar_new(sizeof(xbt_log_setting_t),
718 /* split the string, and remove empty entries */
719 set_strings=xbt_str_split(control_string," ");
720 xbt_dynar_foreach(set_strings,cpt,str) {
721 xbt_str_trim(str,NULL);
723 xbt_dynar_cursor_rm(set_strings,&cpt);
727 if (xbt_dynar_length(set_strings) == 0) { /* vicious user! */
728 xbt_dynar_free(&set_strings);
732 /* Parse each entry and either use it right now (if the category was already
733 created), or store it for further use */
734 xbt_dynar_foreach(set_strings,cpt,str) {
735 xbt_log_category_t cat=NULL;
739 set = _xbt_log_parse_setting(str);
742 cat = _xbt_log_cat_searchsub(&_XBT_LOGV(root),set->catname);
745 if (e.category != not_found_error)
752 DEBUG0("Apply directly");
753 xbt_log_threshold_set(cat,set->thresh);
754 _free_setting((void*)&set);
757 DEBUG0("Store for further application");
758 DEBUG1("push %p to the settings",(void*)set);
759 xbt_dynar_push(xbt_log_settings,&set);
762 xbt_dynar_free(&set_strings);
765 void xbt_log_appender_set(xbt_log_category_t cat, xbt_log_appender_t app) {
769 void xbt_log_additivity_set(xbt_log_category_t cat, int additivity) {
770 cat->additivity = additivity;