Logging System Overview

From Second Life Wiki
Revision as of 07:04, 19 September 2018 by Oz Linden (talk | contribs)
Jump to navigation Jump to search

This document explains how to use the Second Life logging system in the SL Viewer and Simulator, in executable and runtime configuration.

Overview

Enable all developer functionality by including "llerror.h" (in llcommon). Configure runtime settings with the log control file, as described in Runtime control.

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

LOG_CLASS(LLFoo);

For example: 

    
    class LLFoo
    {
        LOG_CLASS(LLFoo);
    public:
        ...
    };

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

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

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

Basic macros

Use the base macros as follows: 

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.

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

Dual tag macros

With dual tag macros, you to bind two string tags to a log message: a "broad" scope tag and a "narrow" scope tag, useful to specify a high granularity and a low granularity tag for a log message. For example, you could specify "AppInit" and "SystemInfo" tags, where "AppInit" is the broad scope tag for 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.

Tag formatting

Format macro tags in "camel case", such as "RenderInit" and "TextureCache".

Tags may not contain whitespace characters

Obsolete macros

In the past, the "llerrs", "llwarns", "llinfos", "lldebugs", and "llendl" macros were less capable versions of the current system. For a long time, they were allowed, but now they have been replaced with those documented here and removed.

Logging a repeating message only once

Sometimes log messages will get triggered repeatedly, filling the log file with the same exact message string over and over. To avoid cases like this, use the "ONCE" macros These macros print the message the first time, prepending "ONCE: " to the message string. Subsequently, when it is triggered with the same message it will print only the 10th, 50th, or every 100th time thereafter. 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;

For example, the following log message: 

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

Will 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! 
   ...

Runtime control

Configuration runtime settings with the log control file, an XML file that the application loads immediately after initialization. First, it tries to load logcontrol-dev.xml. If that file doesn't exist, then it loads logcontrol.xml instead. The application checks the file for changes every couple of seconds and reloads it if necessary.

Put the logcontrol-dev.xml file into your user settings directory before launching the viewer.

Sample Control File

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". 

<llsd>
<map>
    <!-- default-level can be ALL, DEBUG, INFO, WARN, ERROR, or NONE -->
    <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>
                        <!-- entries in 'files' match partial pathnames:
                             everything below indra/ -->
                        <string>newview/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>llui/llbutton.cpp</string>
                        <string>llui/llcombobox.cpp</string>
                    </array>
                <key>tags</key>
                    <array>
                        <string>RenderInit</string>
                    </array>
            </map>
        </array>
</map>
</llsd>

Logging granularity conflict resolution

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

  1. Default log level
  2. BroadScopeTag
  3. File Name
  4. Class Name
  5. Function Name
  6. NarrowScopeTag

The application uses the highest matching priority level found in the log control file to determine whether to print a particular log message. For example, if a given log message is of a class set in the log control file to print all LL_DEBUGS() and below, but there is an entry for its function name that states to print only LL_WARNS() and below, then the system will print only LL_WARNS() and LL_ERRS().

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.

Any computation embedded as above 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;
// 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;

Log Line Format

Log entries are written as a single line formatted as: 

timestamp SPACE level SPACE tags SPACE location SPACE function SPACE COLON SPACE message

Where

  • timestamp is an ISO format date/time stamp like 2018-09-19T13:38:53Z
  • level is the severity level
  • tags is any tag values, surrounded by '#' characters, or a single '#' if there are no tags specified, like #HTTPCore# or #HTTPCore#Initialize#
  • location is the path name (relative to the top level indra directory) and line number in parenthesis like llcorehttp/httpstats.cpp(104)
  • function is the class and method or function name like LLControlGroup::get
  • SPACE is a single space character
  • COLON is a single colon character (':')
  • message is the log message, with any backslash, newline, and return characters escaped (see below)

For example: 

2018-09-19T13:38:53Z WARNING #HTTPCore# llcorehttp/httpstats.cpp(104) dumpStats : HTTP DATA SUMMARY\nHTTP Transfer counts:\nData Sent: 0B   (0)\nData Recv: 0B   (0)\nTotal requests: 4(request objects created)\n\nResult Codes:\n--- -----\n200 1\n

Log Line Escaping

The log message may be multiple lines; any line breaks will be escaped by substituting 

newline → \n
return → \r
\ → \\

This escaping can be undone for readability by piping the log file through a filter like: 

perl -pe 's/\\\\/\\/g; s/\\n/\n/g; s/\\r/\r/g;'

The example line above when run through that filter becomes: 

2018-09-19T13:38:53Z WARNING #HTTPCore# llcorehttp/httpstats.cpp(104) dumpStats : HTTP DATA SUMMARY
HTTP Transfer counts:
Data Sent: 0B   (0)
Data Recv: 0B   (0)
Total requests: 4(request objects created)

Result Codes:
--- -----
200 1
Retrieved from "https://wiki.secondlife.com/w/index.php?title=Logging_System_Overview&oldid=1207528"