Difference between revisions of "Logging System Overview"

From Second Life Wiki
Jump to navigation Jump to search
m
(27 intermediate revisions by 4 users not shown)
Line 3: Line 3:
== Overview ==
== Overview ==


Enable all developer functionality by including "'''llerror.h'''" (in llcommon).   
Enable all developer functionality by including "'''llerror.h'''" (in llcommon).  Configure runtime settings with the log control file, as described in [[#Runtime control|Runtime control]].
 
Configurre runtime settings in the logging configuration file, <code>logcontrol.xml</code> (or <code>logcontrol-dev.xml</code>). 
 
* In the Viewer, located in "'''app_settings/'''" directory
* For the simulator, "'''/opt/linden/etc/'''" ("'''<branch>/etc/'''" on Windows)


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


<cpp>LOG_CLASS(LLFoo);</cpp>
<source lang="cpp">LOG_CLASS(LLFoo);</source>


For example:
For example:


<cpp>    class LLFoo
<source lang="cpp">     
    class LLFoo
     {
     {
         LOG_CLASS(LLFoo);
         LOG_CLASS(LLFoo);
     public:
     public:
         ...
         ...
     };</cpp>
     };</source>


===Output===
===Output===
The Viewer saves log output to <tt>LL_PATH_APP_SETTINGS/logs/SecondLife.log</tt>, where LL_PATH_APP_SETTINGS is:
The Viewer saves log output to <code>LL_PATH_APP_SETTINGS/logs/SecondLife.log</code>, where LL_PATH_APP_SETTINGS is:
* <code>%APPDATA%\SecondLife\</code> on Windows.
* <code>%APPDATA%\SecondLife\</code> on Windows.
* <code>$HOME/Library/Application Support/SecondLife/</code> on MacOS.
* <code>$HOME/Library/Application Support/SecondLife/</code> on MacOS.
Line 34: Line 30:
== Logging macros ==
== Logging macros ==


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 [[Logging_System_Overview#Varying_amount_of_logging_at_runtime|Runtime control]].   
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|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.
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:


 
<source lang="cpp">LL_DEBUGS("BroadScopeTag") << "A debug level log message"  << LL_ENDL;   
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.
// This is a macro, not a string stream.  The "LL_ENDL" is required.
LL_INFOS("BroadScopeTag")  << "An info level log message"  << LL_ENDL;
LL_INFOS("BroadScopeTag")  << "An info level log message"  << LL_ENDL;
LL_WARNS("BroadScopeTag")  << "A warning 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("BroadScopeTag")  << "An error level log message"  << LL_ENDL;   
//  LL_ERRS forces a crash of the viewer.</cpp>
//  LL_ERRS forces a crash of the viewer.</source>
 
'''Note:''' Use [[Logging_System_Overview#Tag_Formatting|CamelCase]] for tags.
 
The logging macros behave like iostreams, and can have anything appended to them that can be appended to an iostream.
 
=== Deprecated macros ===


The old "'''llerrs'''", "'''llwarns'''", "'''llinfos'''", "'''lldebugs'''", and "'''llendl'''" logging macros are '''deprecated''', but still work for backwards compatibilityThe new ones are capitalized per our compiler preprocessor directives naming conventions in the [[Coding_Standard#Naming_Convention|Coding Standards]].
The logging macros behave like iostreamsYou can appended anything to them that can be appended to an iostream.


== Multiple tag logging macros ==
=== Dual tag macros ===


There also exist versions of the macros that allow you to bind two 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.
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.


<cpp>LL_DEBUGS2("BroadScopeTag", "NarrowScopeTag") << "A debug level log message"  << LL_ENDL;   
<source lang="cpp">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.
// 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_INFOS2("BroadScopeTag", "NarrowScopeTag")  << "An info level log message"  << LL_ENDL;
LL_WARNS2("BroadScopeTag", "NarrowScopeTag")  << "A warning 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;     
LL_ERRS2("BroadScopeTag", "NarrowScopeTag")  << "An error level log message"  << LL_ENDL;     
// NOTE: LL_ERRS2 force a crash of the viewer.</cpp>
// NOTE: LL_ERRS2 force a crash of the viewer.</source>


=== Tag formatting ===
=== Tag formatting ===


Format tags in "camel case", such as "RenderInit" and "TextureCache".
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 ==
== 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.
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.
'''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.


<cpp>LL_DEBUGS_ONCE("BroadScopeTag") << "A debug level log message"  << LL_ENDL;   
<source lang="cpp">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.
// 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_INFOS_ONCE("BroadScopeTag")  << "An info level log message"  << LL_ENDL;
Line 86: Line 82:
// NOTE: This is a macro, not a string stream.  The "LL_ENDL" is required.
// 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_INFOS2_ONCE("BroadScopeTag", "NarrowScopeTag")  << "An info level log message"  << LL_ENDL;
LL_WARNS2_ONCE("BroadScopeTag", "NarrowScopeTag")  << "A warning level log message" << LL_ENDL;</cpp>
LL_WARNS2_ONCE("BroadScopeTag", "NarrowScopeTag")  << "A warning level log message" << LL_ENDL;</source>


For example, the following log message:
For example, the following log message:


<cpp>LL_WARNS_ONCE("Drawable") << "Drawable becomes static with active parent!" << LL_ENDL;</cpp>
<source lang="cpp">LL_WARNS_ONCE("Drawable") << "Drawable becomes static with active parent!" << LL_ENDL;</source>


Will print the following messages to <code>SecondLife.log</code> if it kept getting called repeatedly:
Will print the following messages to <code>SecondLife.log</code> if it kept getting called repeatedly:
Line 103: Line 99:
== Runtime control ==
== 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".
Configuration runtime settings with the ''log control file'', an XML file that the application loads immediately
after initialization.  First, it tries to load <code>logcontrol-dev.xml</code>.  If that file doesn't exist, then it loads <code>logcontrol.xml</code> instead.  The application checks the file for changes every couple of seconds and reloads it if necessary.   
 
Put the <code>logcontrol-dev.xml</code> file into your user settings directory '''before launching the viewer'''.
 
=== Sample Control File ===


Sample "'''logcontrol.xml'''" file:
The following is a sample <code>logcontrol.xml</code> 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".


<xml><llsd>
<source lang="xml">
<llsd>
<map>
<map>
     <!-- default-level can be ALL, DEBUG, INFO, WARN, ERROR, or NONE -->
     <!-- default-level can be ALL, DEBUG, INFO, WARN, ERROR, or NONE -->
Line 126: Line 128:
                 <key>files</key>
                 <key>files</key>
                     <array>
                     <array>
                         <string>lldrawpoolavatar.cpp</string>
                        <!-- entries in 'files' match partial pathnames:
                            everything below indra/ -->
                         <string>newview/lldrawpoolavatar.cpp</string>
                     </array>
                     </array>
                 <key>tags</key>
                 <key>tags</key>
Line 144: Line 148:
                 <key>files</key>
                 <key>files</key>
                     <array>
                     <array>
                         <string>llbutton.cpp</string>
                         <string>llui/llbutton.cpp</string>
                         <string>llcombobox.cpp</string>
                         <string>llui/llcombobox.cpp</string>
                     </array>
                     </array>
                 <key>tags</key>
                 <key>tags</key>
Line 154: Line 158:
         </array>
         </array>
</map>
</map>
</llsd></xml>
</llsd></source>


== Logging granularity conflict resolution ==
== Logging granularity conflict resolution ==
Line 160: Line 164:
The logging system decides in the following order what logging granularity to apply to a message:
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'''
# 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.
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 ==
== 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:
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;
<source lang="cpp">   
     LL_DEBUGS("AgentGesture") << "the agent " << agend_id;
     switch (f)
     switch (f)
     {
     {
         case FOP_SHRUGS:  '''LL_CONT''' << "shrugs";              break;
         case FOP_SHRUGS:  LL_CONT << "shrugs";              break;
         case FOP_TAPS:    '''LL_CONT''' << "points at " << who;  break;
         case FOP_TAPS:    LL_CONT << "points at " << who;  break;
         case FOP_SAYS:    '''LL_CONT''' << "says " << message;    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.
     LL_CONT << " for " << t << " seconds" << LL_ENDL;   
</source>
 
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.
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 <code>llfeaturemanager.cpp</code>:
 
<source lang="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;
</source>
 
= 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 <tt>2018-09-19T13:38:53Z</tt>
* ''level'' is the severity level
* ''tags'' is any tag values, surrounded by '#' characters, or a single '#' if there are no tags specified, like <tt>#HTTPCore#</tt> or <tt>#HTTPCore#Initialize#</tt>
* ''location'' is the path name (relative to the top level <tt>indra</tt> directory) and line number in parenthesis like <tt>llcorehttp/httpstats.cpp(104)</tt>
* ''function'' is the class and method or function name like <tt>LLControlGroup::get</tt>
* 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 &rarr; \n
return &rarr; \r
\ &rarr; \\
 
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;'


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:
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)


    '''LL_DEBUGS'''("RenderInit") << "After applying mask " << mask.mName << std::endl;
Result Codes:
        // 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.
200 1
        dump();
    '''LL_CONT''' << '''LL_ENDL''';

Revision as of 07:04, 19 September 2018

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