Logging System Overview

From Second Life Wiki
Jump to navigation Jump to search

This document explains both the use of our log message system in code and how to control it at runtime to determine what events are logged.

Overview

All developer functionality is enabled by "llerror.h" (in llcommon).

All runtime changing of logging granularity is done by editing "logcontrol.xml" or "logcontrol-dev.xml", which are located in the "app_settings/" directory for the viewer and in "/opt/linden/etc/" for the server ("<branch>/etc/" on Windows).

To get the maximum utility out of the log system, add the following to the private section of your class declaration:

<cpp>LOG_CLASS(LLFoo);</cpp>

For example:

<cpp> class LLFoo 

   {
       LOG_CLASS(LLFoo);
   public:
       ...
   };</cpp>

Output

The Viewer saves log output to LL_PATH_APP_SETTINGS/logs/SecondLife.log, where LL_PATH_APP_SETTINGS is:

  • %APPDATA%\SecondLife\ on Windows.
  • $HOME/Library/Application Support/SecondLife/ on MacOS.
  • $HOME/.secondlife/ on Linux.

The server sends log output to /var/log/indra.log.

Logging Macros

The old "llerrs", "llwarns", "llinfos", "lldebugs", and "llendl" logging macros are deprecated, but still work for backwards compatibility. The new ones are capitalized per our compiler preprocessor directives naming conventions in the Coding Standards.

To selectively enable or disable log messages at runtime, use log message string tags (a "broad" scope tag and a "narrow" scope tag). For an example, see the <key>tags</key> block in Varying amount of logging at runtime.

If you really don't want to tag a message, pass NULL to the macro. However, the overhead of logging a message is small.

The new base macros are used as follows:

<cpp>LL_DEBUGS("BroadScopeTag") << "A debug level log message" << LL_ENDL; // This is a macro, not a string stream. The "LL_ENDL" is required. LL_INFOS("BroadScopeTag") << "An info level log message" << LL_ENDL; LL_WARNS("BroadScopeTag") << "A warning level log message" << LL_ENDL; LL_ERRS("BroadScopeTag") << "An error level log message" << LL_ENDL; // LL_ERRS forces a crash of the viewer.</cpp>

Note: Use CamelCase for tags.

The logging macros behave like iostreams, and can have anything appended to them that can be appended to an iostream.

Multiple Tag Logging Macros

There also exist versions of the macros that allow you to bind 2 string tags to a log message (a "broad" scope tag and a "narrow" scope tag), which is very useful when you want to have both high and low granularity for tagging a log message (for example "AppInit" and "SystemInfo", where "AppInit" is the broad scope tag and describes the long Application Initialization process of which the narrow scope tag "SystemInfo" printing is a small portion). 

   LL_DEBUGS2("BroadScopeTag", "NarrowScopeTag") << "A debug level log message"   << LL_ENDL;   // NOTE: This is a macro, not a string stream.  The "LL_ENDL" is required.
   LL_INFOS2("BroadScopeTag", "NarrowScopeTag")  << "An info level log message"   << LL_ENDL;
   LL_WARNS2("BroadScopeTag", "NarrowScopeTag")  << "A warning level log message" << LL_ENDL;
   LL_ERRS2("BroadScopeTag", "NarrowScopeTag")   << "An error level log message"  << LL_ENDL;    // NOTE: LL_ERRS2 force a crash of the viewer.
   
   Note: Tags should be formatted in CamelCase

Logging a repeating message only once

There are currently some log messages that if triggered end up spamming the log file with the same exact message string over and over. As a result, we now also have the ability to use a special macro that keeps these messages from filling up the log and drowning out other messages. These macros will print the message the first time it gets triggered and prepends "ONCE: " to the message string. Any further time it is triggered with the same message it will not print it, unless it is the 10th, 50th, or every 100th time there after that it is encountered. Then, it updates you by prepending "ONCE (Nth time seen): " to the log message, where N is the number of times it has been seen.

Note: This works on unique final log messages, so log messages that depend on one or more variables have the final output treated as different messages if any part of the string changes. Thus, you should not use _ONCE macros for log messages that will print many times but with different messages, as this would be slightly slower and would slowly fill up a std::map with memory occupying junk. 

  LL_DEBUGS_ONCE("BroadScopeTag") << "A debug level log message"   << LL_ENDL;   // NOTE: This is a macro, not a string stream.  The "LL_ENDL" is required.
  LL_INFOS_ONCE("BroadScopeTag")  << "An info level log message"   << LL_ENDL;
  LL_WARNS_ONCE("BroadScopeTag")  << "A warning level log message" << LL_ENDL;
  
  LL_DEBUGS2_ONCE("BroadScopeTag", "NarrowScopeTag") << "A debug level log message"   << LL_ENDL;   // NOTE: This is a macro, not a string stream.  The "LL_ENDL" is required.
  LL_INFOS2_ONCE("BroadScopeTag", "NarrowScopeTag")  << "An info level log message"   << LL_ENDL;
  LL_WARNS2_ONCE("BroadScopeTag", "NarrowScopeTag")  << "A warning level log message" << LL_ENDL;
  
  Note: Tags should be formatted in CamelCase

For example, the following log message: 

   LL_WARNS_ONCE("Drawable") << "Drawable becomes static with active parent!" << LL_ENDL;

would print the following messages to "SecondLife.log" if it kept getting called repeatedly: 

   WARNING: LLDrawable::makeStatic: ONCE: Drawable becomes static with active parent! 
   WARNING: LLDrawable::makeStatic: ONCE (10th time seen): Drawable becomes static with active parent! 
   WARNING: LLDrawable::makeStatic: ONCE (50th time seen): Drawable becomes static with active parent! 
   WARNING: LLDrawable::makeStatic: ONCE (100th time seen): Drawable becomes static with active parent! 
   WARNING: LLDrawable::makeStatic: ONCE (200th time seen): Drawable becomes static with active parent! 
   ... etc ...

Tag Formatting

Tags should be formatted in "CamelCase", such as "RenderInit" and "TextureCache"

Runtime control

Upon initialization of the application, the logging system tries to load a "logcontrol-dev.xml" file and if it doesn't exist, it loads "logcontrol.xml" instead. These files are located in the "app_settings/" directory for the viewer and in "/opt/linden/etc/" for the server ("<branch>/etc/" on Windows). Whichever file is loaded gets checked for changes every couple of seconds and reloaded if necessary. The following is a sample logcontrol.xml file that sets the default loggging level to WARN and then conditionally turns on some warnings at INFO level and DEBUG level based on "function name", "class name", "file name", and "tag".

Sample "logcontrol.xml" file:

<xml> <llsd> <map> 

   <key>default-level</key>    <string>WARN</string>
   <key>print-location</key>   <boolean>false</boolean>
   <key>settings</key
       <array>
           <map>
               <key>level</key><string>INFO</string>
               <key>functions</key>
                   <array>
                       <string>LLAgentInfo::handleImageRequest</string>
                   </array>
               <key>classes</key>
                   <array>
                       <string>LLBufferArray</string>
                   </array>
               <key>files</key>
                   <array>
                       <string>lldrawpoolavatar.cpp</string>
                   </array>
               <key>tags</key>
                   <array>
                       <string>AppInit</string>
                       <string>TextureCache</string>
                   </array>
           </map>
           <map>
               <key>level</key><string>DEBUG</string>
               <key>functions</key>
                   <array>
                   </array>
               <key>classes</key>
                   <array>
                   </array>
               <key>files</key>
                   <array>
                       <string>llbutton.cpp</string>
                       <string>llcombobox.cpp</string>
                   </array>
               <key>tags</key>
                   <array>
                       <string>RenderInit</string>
                   </array>
           </map>
       </array>

</map> </llsd> </xml>

Logging granularity conflict resolution

The logging system decides in the following order what logging granularity to apply to a message:

Default log level < BroadScopeTag < File Name < Class Name < Function Name < NarrowScopeTag

Thus, highest priority level match found in "logcontrol.xml" is used to decide if a particular log message should be printed. For example, if a given log message is of a class that has been set in "logcontrol.xml" to print all LL_DEBUGS() and below, but there is an entry for its function name that states to only print LL_WARNS() and below, then only LL_WARNS() and LL_ERRS() will be printed.

Continuing a log message after further computation

Use the LL_CONT macro if you need to do computation in the middle of a log message: 

   LL_DEBUGS("AgentGesture") << "the agent " << agend_id;
   switch (f)
   {
       case FOP_SHRUGS:   LL_CONT << "shrugs";              break;
       case FOP_TAPS:     LL_CONT << "points at " << who;   break;
       case FOP_SAYS:     LL_CONT << "says " << message;    break;
   }
   LL_CONT << " for " << t << " seconds" << LL_ENDL;   // Make sure to remember the LL_ENDL at the end and ONLY at the end.

Such computation is done only if the message will be logged.

This means that you can also use the macro functionality to conditionally call separate functions only if that granularity of logging is enabled, such as in the following example from llfeaturemanager.cpp: 

   LL_DEBUGS("RenderInit") << "After applying mask " << mask.mName << std::endl;
       // Will conditionally call dump only if the above message will be logged, thanks 
       // to it being wrapped by the LL_DEBUGS and LL_ENDL macros.
       dump();
   LL_CONT << LL_ENDL;
Retrieved from "https://wiki.secondlife.com/w/index.php?title=Logging_System_Overview&oldid=502303"