X-Git-Url: http://info.iut-bm.univ-fcomte.fr/pub/gitweb/simgrid.git/blobdiff_plain/ffa7c2b3103319030c88a966e9c65f4c418a3449..bf04b8efb92e60adf389face2d957846ce7721be:/src/xbt/log.c diff --git a/src/xbt/log.c b/src/xbt/log.c index 0ecdfd6541..d158ee564d 100644 --- a/src/xbt/log.c +++ b/src/xbt/log.c @@ -2,7 +2,7 @@ /* log - a generic logging facility in the spirit of log4j */ -/* Copyright (c) 2003, 2004 Martin Quinson. All rights reserved. */ +/* Copyright (c) 2003-2007 Martin Quinson. All rights reserved. */ /* This program is free software; you can redistribute it and/or modify it * under the terms of the license (GNU LGPL) which comes with this package. */ @@ -20,7 +20,7 @@ #include "xbt/misc.h" #include "xbt/ex.h" #include "xbt/sysdep.h" -#include "xbt/log.h" +#include "xbt/log_private.h" #include "xbt/dynar.h" XBT_PUBLIC_DATA(int) (*xbt_pid)(); @@ -40,11 +40,16 @@ XBT_PUBLIC_DATA(int) (*xbt_pid)(); - \ref log_API - \ref log_API_cat - \ref log_API_pri + - \ref log_API_isenabled - \ref log_API_subcat - \ref log_API_easy - \ref log_API_example - \ref log_user - \ref log_use_conf + - \ref log_use_conf_thres + - \ref log_use_conf_multi + - \ref log_use_conf_fmt + - \ref log_use_conf_add - \ref log_use_misc - \ref log_internals - \ref log_in_perf @@ -102,10 +107,6 @@ stuff on stderr. But everything is in place internally to write new ones, such as the one able to send the strings to a central server in charge of syndicating the logs of every distributed daemons on a well known location. -It should also be possible to pass configuration informations to the appenders, -specifying for example that the message location (file and line number) is only -relevant to debugging information, not to critical error messages. - One day, for sure ;) \subsection log_lay 1.4 Message layouts @@ -115,50 +116,8 @@ will look like. Their result is a string which is then passed to the appender attached to the category to be displayed. For now, there is two layouts: The simple one, which is good for most cases, -and another one allowing users to specify the format they want. - -Here are the existing format directives: - - - %%: the % char - - %n: platform-dependant line separator (LOG4J compliant) - - %e: plain old space (SimGrid extension) - - - %m: user-provided message - - - %c: Category name (LOG4J compliant) - - %p: Priority name (LOG4J compliant) - - - %h: Hostname (SimGrid extension) - - %t: Process name (LOG4J compliant -- thread name in LOG4J) - - %I: Process PID (SimGrid extension) - - - %F: file name where the log event was raised (LOG4J compliant) - - %l: location where the log event was raised (LOG4J compliant, like '%F:%L') - - %L: line number where the log event was raised (LOG4J compliant) - - %M: function name (LOG4J compliant -- called method name here of course). - Defined only when using gcc because there is no __FUNCTION__ elsewhere. - - - %b: full backtrace (Called %throwable in LOG4J). - Defined only when using the GNU libc because backtrace() is not defined - elsewhere. - - %B: short backtrace (only the first line of the %b). - Called %throwable{short} in LOG4J, defined where %b is. - - - %d: date (UNIX epoch) - - %r: application age (time elapsed since the beginning of the application) - - -If you want to mimick the simple layout with the format one, you would use this -format: '[%h:%i:(%I) %r] %l: [%c/%p] %m%n'. This is not completely correct -because the simple layout do not display the message location for messages at -priority INFO (thus, the fmt is '[%h:%i:(%I) %r] %l: [%c/%p] %m%n' in this -case). Moreover, if there is no process name (ie, messages comming from the -library itself, or test programs doing strange things) do not display the -process identity (thus, fmt is '[%r] %l: [%c/%p] %m%n' in that case, and '[%r] -[%c/%p] %m%n' if they are at priority INFO). - -For now, there is only one format modifyier: the precision field. You can for -example specify %.4r to get the application age with 4 numbers after the radix. +and another one allowing users to specify the format they want. +\ref log_use_conf provides more info on this. \subsection log_hist 1.5 History of this module @@ -241,18 +200,28 @@ equivalent to the shorter: CWARN4(MyCat, "Values are: %d and '%s'", 5, "oops"); -\section log_API_subcat 2.3 Using a default category (the easy interface) +\section log_API_isenabled 2.3 Checking if a perticular category/priority is enabled + +It is sometimes useful to check whether a perticular category is +enabled at a perticular priority. One example is when you want to do +some extra computation to prepare a nice debugging message. There is +no use of doing so if the message won't be used afterward because +debugging is turned off. + +Doing so is extremely easy, thanks to the XBT_LOG_ISENABLED(category, priority). + +\section log_API_subcat 2.4 Using a default category (the easy interface) If \ref XBT_LOG_NEW_DEFAULT_SUBCATEGORY(MyCat, Parent) or \ref XBT_LOG_NEW_DEFAULT_CATEGORY(MyCat) is used to create the category, then the even shorter form can be used: -WARN3("Values are: %d and '%s'", 5, "oops"); +WARN3("Values are: %s and '%d'", 5, "oops"); Only one default category can be created per file, though multiple non-defaults can be created and used. -\section log_API_easy 2.4 Putting all together: the easy interface +\section log_API_easy 2.5 Putting all together: the easy interface First of all, each module should register its own category into the categories tree using \ref XBT_LOG_NEW_DEFAULT_SUBCATEGORY. @@ -280,7 +249,7 @@ The TRACE priority is not used the same way than the other. You should use the #XBT_IN, XBT_IN (up to #XBT_IN5), #XBT_OUT and #XBT_HERE macros instead. -\section log_API_example 2.5 Example of use +\section log_API_example 2.6 Example of use Here is a more complete example: @@ -295,17 +264,17 @@ int main() { / * Now set the parent's priority. (the string would typcially be a runtime option) * / xbt_log_control_set("SA.thresh:3"); - / * This request is enabled, because WARNING >= INFO. * / + / * This request is enabled, because WARNING >= INFO. * / CWARN2(VSS, "Low fuel level."); - / * This request is disabled, because DEBUG < INFO. * / + / * This request is disabled, because DEBUG < INFO. * / CDEBUG2(VSS, "Starting search for nearest gas station."); / * The default category SA inherits its priority from VSS. Thus, - the following request is enabled because INFO >= INFO. * / + the following request is enabled because INFO >= INFO. * / INFO1("Located nearest gas station."); - / * This request is disabled, because DEBUG < INFO. * / + / * This request is disabled, because DEBUG < INFO. * / DEBUG1("Exiting gas station search"); } \endverbatim @@ -316,23 +285,100 @@ Another example can be found in the relevant part of the GRAS tutorial: \section log_user 3. User interface \section log_use_conf 3.1 Configuration -Configuration is typically done during program initialization by invoking -the xbt_log_control_set() method. The control string passed to it typically -comes from the command line. Look at the documentation for that function for -the format of the control string. - -Any SimGrid program can furthermore be configured at run time by passing a ---xbt-log argument on the command line (--gras-log, --msg-log and --surf-log -are synonyms provided by aestheticism). You can provide several of those -arguments to change the setting of several categories, they will be applied -from left to right. So, -\verbatim --xbt-log="root.thres:debug root.thres:critical"\endverbatim -should disable any logging. +Although rarely done, it is possible to configure the logs during +program initialization by invoking the xbt_log_control_set() method +manually. A more conventionnal way is to use the --log command line +argument. xbt_init() (called by MSG_init(), gras_init() and friends) +checks and deals properly with such arguments. + +The following command line arguments exist, but are deprecated and +may disapear in the future: --xbt-log, --gras-log, --msg-log and +--surf-log. + +\subsection log_use_conf_thres 3.1.1 Thresold configuration + +The most common setting is to control which logging event will get +displayed by setting a threshold to each category through the +thres keyword. + +For example, \verbatim --log=root.thres:debug\endverbatim will make +SimGrid extremely verbose while \verbatim +--log=root.thres:critical\endverbatim should shut it almost +completely off. + +\subsection log_use_conf_multi 3.1.2 Passing several settings + +You can provide several of those arguments to change the setting of several +categories, they will be applied from left to right. So, +\verbatim --log="root.thres:debug root.thres:critical"\endverbatim should +disable almost any logging. + Note that the quotes on above line are mandatory because there is a space in the argument, so we are protecting ourselves from the shell, not from SimGrid. We could also reach the same effect with this: -\verbatim --xbt-log=root.thres:debug --xbt-log=root.thres:critical\endverbatim +\verbatim --log=root.thres:debug --log=root.thres:critical\endverbatim + +\subsection log_use_conf_fmt 3.1.3 Format configuration + +As with SimGrid 3.3, it is possible to control the format of log +messages. This is done through the fmt keyword. For example, +\verbatim --log=root.fmt:%m\endverbatim reduces the output to the +user-message only, removing any decoration such as the date, or the +process ID, everything. + +Here are the existing format directives: + + - %%: the % char + - %%n: platform-dependant line separator (LOG4J compliant) + - %%e: plain old space (SimGrid extension) + + - %%m: user-provided message + + - %%c: Category name (LOG4J compliant) + - %%p: Priority name (LOG4J compliant) + + - %%h: Hostname (SimGrid extension) + - %%P: Process name (SimGrid extension) + - %%t: Thread "name" (LOG4J compliant -- actually the address of the thread in memory) + - %%i: Process PID (SimGrid extension -- this is a 'i' as in 'i'dea) + + - %%F: file name where the log event was raised (LOG4J compliant) + - %%l: location where the log event was raised (LOG4J compliant, like '%%F:%%L' -- this is a l as in 'l'etter) + - %%L: line number where the log event was raised (LOG4J compliant) + - %%M: function name (LOG4J compliant -- called method name here of course). + Defined only when using gcc because there is no __FUNCTION__ elsewhere. + + - %%b: full backtrace (Called %%throwable in LOG4J). + Defined only when using the GNU libc because backtrace() is not defined + elsewhere. + - %%B: short backtrace (only the first line of the %%b). + Called %%throwable{short} in LOG4J; defined where %%b is. + + - %%d: date (UNIX-like epoch) + - %%r: application age (time elapsed since the beginning of the application) + + +If you want to mimick the simple layout with the format one, you would use this +format: '[%%h:%%i:(%%I) %%r] %%l: [%%c/%%p] %%m%%n'. This is not completely correct +because the simple layout do not display the message location for messages at +priority INFO (thus, the fmt is '[%%h:%%i:(%%I) %%r] %%l: [%%c/%%p] %%m%%n' in this +case). Moreover, if there is no process name (ie, messages comming from the +library itself, or test programs doing strange things) do not display the +process identity (thus, fmt is '[%%r] %%l: [%%c/%%p] %%m%%n' in that case, and '[%%r] +[%%c/%%p] %%m%%n' if they are at priority INFO). + +For now, there is only one format modifyier: the precision field. You +can for example specify %.4r to get the application age with 4 +numbers after the radix. Another limitation is that you cannot set +specific layouts to the several priorities. + +\subsection log_use_conf_add 3.1.4 Category additivity + +The add keyword allows to specify the additivity of a +category (see \ref log_in_app). This is rarely useful since you +cannot specify an alternative appender. Anyway, '0', '1', 'no', +'yes', 'on' and 'off' are all valid values, with 'yes' as default. \section log_use_misc 3.2 Misc and Caveats @@ -344,10 +390,12 @@ We could also reach the same effect with this: \section log_internals 4. Internal considerations -This module is a mess of macro black magic, and when it goes wrong, SimGrid -studently loose its ability to explain its problems. When messing around this -module, I often find useful to define XBT_LOG_MAYDAY (which turns it back to -good old printf) for the time of finding what's going wrong. +This module is a mess of macro black magic, and when it goes wrong, +SimGrid studently loose its ability to explain its problems. When +messing around this module, I often find useful to define +XBT_LOG_MAYDAY (which turns it back to good old printf) for the time +of finding what's going wrong. But things are quite verbose when +everything is enabled... \section log_in_perf 4.1 Performance @@ -358,7 +406,7 @@ There is also compile time constant, \ref XBT_LOG_STATIC_THRESHOLD, which causes all logging requests with a lower priority to be optimized to 0 cost by the compiler. By setting it to gras_log_priority_infinite, all logging requests are statically disabled and cost nothing. Released executables -might be compiled with +might be compiled with (note that it will prevent users to debug their problems) \verbatim-DXBT_LOG_STATIC_THRESHOLD=gras_log_priority_infinite\endverbatim Compiling with the \verbatim-DNLOG\endverbatim option disables all logging @@ -433,16 +481,19 @@ const char *xbt_log_priority_names[8] = { "CRITICAL" }; -XBT_PUBLIC_DATA(s_xbt_log_category_t) _XBT_LOGV(XBT_LOG_ROOT_CAT) = { - 0, 0, 0, - "root", xbt_log_priority_uninitialized, 0, - NULL, 0 +s_xbt_log_category_t _XBT_LOGV(XBT_LOG_ROOT_CAT) = { + NULL /*parent*/, NULL /* firstChild */, NULL /* nextSibling */, + "root", xbt_log_priority_uninitialized /* threshold */, + 0 /* isThreshInherited */, + NULL /* appender */, NULL /* layout */, + 0 /* additivity */ }; XBT_LOG_NEW_CATEGORY(xbt,"All XBT categories (simgrid toolbox)"); XBT_LOG_NEW_CATEGORY(surf,"All SURF categories"); XBT_LOG_NEW_CATEGORY(msg,"All MSG categories"); XBT_LOG_NEW_CATEGORY(simix,"All SIMIX categories"); + XBT_LOG_NEW_DEFAULT_SUBCATEGORY(log,xbt,"Loggings from the logging mechanism itself"); /** @brief Get all logging settings from the command line @@ -459,7 +510,9 @@ void xbt_log_init(int *argc,char **argv) { xbt_log_default_layout = xbt_log_layout_simple_new(NULL); _XBT_LOGV(XBT_LOG_ROOT_CAT).appender = xbt_log_default_appender; _XBT_LOGV(XBT_LOG_ROOT_CAT).layout = xbt_log_default_layout; - _log_usable = 1; + _log_usable = 1; + +// _XBT_LOGV(log).threshold = xbt_log_priority_debug; /* uncomment to set the LOG category to debug directly */ /* Set logs and init log submodule */ for (i=1; i<*argc; i++){ @@ -520,21 +573,21 @@ void _xbt_log_event_log( xbt_log_event_t ev, const char *fmt, ...) { xbt_log_category_t cat = ev->cat; if (!_log_usable) { - fprintf(stderr,"XXXXXXXXXXXXXXXXXXX\nXXX Warning, logs not usable here. Either before xbt_init() or after xbt_exit().\nXXXXXXXXXXXXXXXXXXX\n"); - va_start(ev->ap, fmt); - vfprintf(stderr,fmt,ev->ap); - va_end(ev->ap); - xbt_backtrace_display(); - return; + /* Make sure that the layouts have been malloced */ + xbt_log_default_appender = xbt_log_appender_file_new(NULL); + xbt_log_default_layout = xbt_log_layout_simple_new(NULL); + _XBT_LOGV(XBT_LOG_ROOT_CAT).appender = xbt_log_default_appender; + _XBT_LOGV(XBT_LOG_ROOT_CAT).layout = xbt_log_default_layout; + _log_usable = 1; } va_start(ev->ap, fmt); + va_start(ev->ap_copy, fmt); while(1) { xbt_log_appender_t appender = cat->appender; if (appender != NULL) { xbt_assert1(cat->layout,"No valid layout for the appender of category %s",cat->name); - char *str= cat->layout->do_layout(cat->layout, ev, fmt); - appender->do_append(appender, str); + cat->layout->do_layout(cat->layout, ev, fmt, appender); } if (!cat->additivity) break; @@ -542,6 +595,7 @@ void _xbt_log_event_log( xbt_log_event_t ev, const char *fmt, ...) { cat = cat->parent; } va_end(ev->ap); + va_end(ev->ap_copy); } static void _xbt_log_cat_apply_set(xbt_log_category_t category, @@ -612,7 +666,20 @@ int _xbt_log_cat_init(xbt_log_category_t category, xbt_log_setting_t setting=NULL; int found = 0; s_xbt_log_event_t _log_ev; - + + if (_XBT_LOGV(log).threshold <= xbt_log_priority_debug + && _XBT_LOGV(log).threshold != xbt_log_priority_uninitialized) { + _log_ev.cat = &_XBT_LOGV(log); + _log_ev.priority = xbt_log_priority_debug; + _log_ev.fileName = __FILE__ ; + _log_ev.functionName = _XBT_FUNCTION ; + _log_ev.lineNum = __LINE__ ; + _xbt_log_event_log(&_log_ev, "Initializing category '%s' (firstChild=%s, nextSibling=%s)", + category->name, + (category->firstChild ?category->firstChild->name :"none"), + (category->nextSibling?category->nextSibling->name:"none")); + } + if(category == &_XBT_LOGV(XBT_LOG_ROOT_CAT)){ category->threshold = xbt_log_priority_info;/* xbt_log_priority_debug*/; category->appender = xbt_log_default_appender; @@ -622,7 +689,38 @@ int _xbt_log_cat_init(xbt_log_category_t category, if (!category->parent) category->parent = &_XBT_LOGV(XBT_LOG_ROOT_CAT); + if (_XBT_LOGV(log).threshold <= xbt_log_priority_debug + && _XBT_LOGV(log).threshold != xbt_log_priority_uninitialized) { + _log_ev.lineNum = __LINE__ ; + _xbt_log_event_log(&_log_ev, "Set %s (%s) as father of %s ", category->parent->name, + (category->parent->threshold == xbt_log_priority_uninitialized ? "uninited":xbt_log_priority_names[category->parent->threshold]), + category->name); + } xbt_log_parent_set(category, category->parent); + + if (_XBT_LOGV(log).threshold < xbt_log_priority_info + && _XBT_LOGV(log).threshold != xbt_log_priority_uninitialized) { + char *buf,*res=NULL; + xbt_log_category_t cpp = category->parent->firstChild; + while (cpp) { + if (res) { + buf = bprintf("%s %s",res,cpp->name); + free(res); + res = buf; + } else { + res = xbt_strdup(cpp->name); + } + cpp = cpp->nextSibling; + } + + _log_ev.lineNum = __LINE__ ; + _xbt_log_event_log(&_log_ev, + "Childs of %s: %s; nextSibling: %s", category->parent->name,res, + (category->parent->nextSibling?category->parent->nextSibling->name:"none")); + + free(res); + } + } /* Apply the control */ @@ -648,7 +746,7 @@ int _xbt_log_cat_init(xbt_log_category_t category, if (!found && category->threshold <= xbt_log_priority_verbose) { - _log_ev.cat = category; + _log_ev.cat = &_XBT_LOGV(log); _log_ev.priority = xbt_log_priority_verbose; _log_ev.fileName = __FILE__ ; _log_ev.functionName = _XBT_FUNCTION ; @@ -663,8 +761,7 @@ int _xbt_log_cat_init(xbt_log_category_t category, return priority >= category->threshold; } -void xbt_log_parent_set(xbt_log_category_t cat,xbt_log_category_t parent) -{ +void xbt_log_parent_set(xbt_log_category_t cat,xbt_log_category_t parent) { xbt_assert0(cat,"NULL category to be given a parent"); xbt_assert1(parent,"The parent category of %s is NULL",cat->name); @@ -814,15 +911,22 @@ static xbt_log_setting_t _xbt_log_parse_setting(const char* control_string) { } static xbt_log_category_t _xbt_log_cat_searchsub(xbt_log_category_t cat,char *name) { - xbt_log_category_t child; + xbt_log_category_t child,res; + DEBUG4("Search '%s' into '%s' (firstChild='%s'; nextSibling='%s')",name,cat->name, + (cat->firstChild ? cat->firstChild->name :"none"), + (cat->nextSibling ? cat->nextSibling->name:"none")); if (!strcmp(cat->name,name)) return cat; - for(child=cat->firstChild ; child != NULL; child = child->nextSibling) - return _xbt_log_cat_searchsub(child,name); - - THROW1(not_found_error,0,"No such category: %s", name); + for (child=cat->firstChild ; child != NULL; child = child->nextSibling) { + DEBUG1("Dig into %s",child->name); + res = _xbt_log_cat_searchsub(child,name); + if (res) + return res; + } + + return NULL; } /** @@ -875,22 +979,11 @@ void xbt_log_control_set(const char* control_string) { created), or store it for further use */ xbt_dynar_foreach(set_strings,cpt,str) { xbt_log_category_t cat=NULL; - int found=0; - xbt_ex_t e; set = _xbt_log_parse_setting(str); + cat = _xbt_log_cat_searchsub(&_XBT_LOGV(XBT_LOG_ROOT_CAT),set->catname); - TRY { - cat = _xbt_log_cat_searchsub(&_XBT_LOGV(root),set->catname); - found = 1; - } CATCH(e) { - if (e.category != not_found_error) - RETHROW; - xbt_ex_free(e); - found = 0; - } - - if (found) { + if (cat) { DEBUG0("Apply directly"); _xbt_log_cat_apply_set(cat,set); _free_setting((void*)&set);