DXi Application Logging Explained

Overview

This topic explains some of the basics around DXi application logging.

Log Handling Software

The logging software used on the DXi is called Log4cplus. More information can be found on their website at: http://log4cplus.sourceforge.net/ .

Log Server Configuration

The first part of the configuration is the network ports and IP addresses to be used. This information is found in /opt/DXi/log.conf:

log.conf

---------------------------------------------------------------------------------------------------------------------------------------------------------------

## ********************************************************** **

## **

## ********************************************************** **

include = /opt/DXi/log-common.conf

#-------- HA appender writes HA cluster messages to tsunami_ha.log via server -----------

log4cplus.appender.HA_APP = log4cplus::SocketAppender

log4cplus.appender.HA_APP.port = 9998

log4cplus.appender.HA_APP.host = 127.0.0.1

#-------- LC appender will be written to tsunami_lc.log via server ------------------

log4cplus.appender.LC_APP = log4cplus::SocketAppender

log4cplus.appender.LC_APP.port = 9998

log4cplus.appender.LC_APP.host = 127.0.0.1

#-------- PERF appender will be written to tsunami_trace.log via server ------------------

log4cplus.appender.PERF_APP = log4cplus::SocketAppender

log4cplus.appender.PERF_APP.port = 9998

log4cplus.appender.PERF_APP.host = 127.0.0.1

#-------- ALL appender, write all messages to server ------------------

log4cplus.appender.ALL_APP = log4cplus::SocketAppender

log4cplus.appender.ALL_APP.port = 9998

log4cplus.appender.ALL_APP.host = 127.0.0.1

---------------------------------------------------------------------------------------------------------------------------------------------------------------

These settings should never be changed.

log-server.conf

The next configuration file is log-server.conf. This file defines how logs are written, and how the log files are stored (size and quantity of files to keep before rolling):

---------------------------------------------------------------------------------------------------------------------------------------------------------------

#-------- ALL appender, write all messages to a file ------------------

log4cplus.appender.ALL_APP = log4cplus::RollingFileAppender

log4cplus.appender.ALL_APP.File = /var/log/DXi/tsunami.log

log4cplus.appender.ALL_APP.MaxFileSize = 200MB

log4cplus.appender.ALL_APP.MaxBackupIndex = 7

# append to a file

log4cplus.appender.ALL_APP.Append = true

# buffer logs for better performance

log4cplus.appender.ALL_APP.ImmediateFlush = true

# appender ignores messages below TRACE level

#log4cplus.appender.ALL_APP.Threshold = TRACE

log4cplus.appender.ALL_APP.layout = log4cplus::PatternLayout

# XXX do not change this pattern! Code in WPUtilitiesLogViewer.cpp relies

# on this format. Breaking makes the GUI no longer able to show the logs.

log4cplus.appender.ALL_APP.layout.ConversionPattern = %-6p - %D{%x-%H:%M:%S} - %c %F(%L) %m%n

#--------"HA appender writes HA cluster messages to tsunami_ha.log" -----------

log4cplus.appender.HA_APP = log4cplus::RollingFileAppender

log4cplus.appender.HA_APP.File = /var/log/DXi/tsunami_ha.log

log4cplus.appender.HA_APP.MaxFileSize = 50MB

log4cplus.appender.HA_APP.MaxBackupIndex = 5

log4cplus.appender.HA_APP.Append = true

log4cplus.appender.HA_APP.ImmediateFlush = true

log4cplus.appender.HA_APP.layout = log4cplus::PatternLayout

log4cplus.appender.HA_APP.layout.ConversionPattern = %-6p - %D{%x-%H:%M:%S} - %c %F(%L) %m%n

#--------"LC appender will be written to tsunami_lc.log" ------------------

log4cplus.appender.LC_APP = log4cplus::RollingFileAppender

log4cplus.appender.LC_APP.File = /var/log/DXi/tsunami_lc.log

log4cplus.appender.LC_APP.MaxFileSize = 200MB

log4cplus.appender.LC_APP.MaxBackupIndex = 10

log4cplus.appender.LC_APP.Append = true

log4cplus.appender.LC_APP.ImmediateFlush = true

log4cplus.appender.LC_APP.layout = log4cplus::PatternLayout

log4cplus.appender.LC_APP.layout.ConversionPattern = %-6p - %D{%x-%H:%M:%S} - %c %F(%L) %m%n

#--------"PERF appender will be written to tsunami_trace.log" ------------------

log4cplus.appender.PERF_APP = log4cplus::RollingFileAppender

log4cplus.appender.PERF_APP.File = /var/log/DXi/tsunami_trace.log

log4cplus.appender.PERF_APP.MaxFileSize = 200MB

log4cplus.appender.PERF_APP.MaxBackupIndex = 10

log4cplus.appender.PERF_APP.Append = true

log4cplus.appender.PERF_APP.ImmediateFlush = true

log4cplus.appender.PERF_APP.layout = log4cplus::PatternLayout

log4cplus.appender.PERF_APP.layout.ConversionPattern = %-6p - %D{%x-%H:%M:%S} - %c %F(%L) %m%n

---------------------------------------------------------------------------------------------------------------------------------------------------------------

log-common.conf

This is the file where logging levels are controlled and loggers are created. It is important to understand how this works from a high level, so that you can access the logs required to troubleshoot a specific issue. Significant points include:

Code that uses log4cplus defines a "logger".
This logger is used throughout the code file to generate log entries.
Different severities for these entries include INFO, WARN, ERROR, DEBUG and TRACE.
The person writing the code determines the severity and the output of these log entries.
A logger is then added to log-common.conf so that it can be managed in a single centralized location.
If a logger is defined in the code, but not in log-common.conf. The log entries for that code are not captured.
By default, we have a set of loggers in log-common.conf. The severity for all of them is set to INFO or INHERIT (which inherits INFO from the parent logger).
INFO includes INFO, WARN, and ERROR.

Let's take a look at some logging for replicationd as an example:

Code file for 2.2.1.3 QuantumVTL/lib/tsunami/Blockpool/RE/ReplicationAPI.cpp:
- replicationd logger defined on line 16702:

16702 qntm_log::logger repLog("replicationd");

In log-common.conf we have:

# allow INFO level and up messages for replication

log4cplus.logger.replicationd = INFO, ALL_APP

log4cplus.additivity.replicationd = false

Looking at the setGlobalReplicationPauseStatus() function in ReplicationAPI.cpp, starting at line 16703, right after the logger definition above, we see:

16703 if (pauseValue == true)

16704 {

16705 QLOG_INFO_S(repLog, "User has paused the replication service");

16706 }

16707 else

16708 {

16709 QLOG_INFO_S(repLog, "User has resumed the replication service");

16710 }

This means that if replication is paused, we should see an INFO message generated in tsunami that says, "User has paused the replication service".
- For WARN, ERROR, or DEBUG you would see QLOG_WARN, QLOG_ERROR or QLOG_DEBUG, respectively

After pausing replication on a lab box, we get the following in tsunami:

INFO - 08/28/13-11:22:22 - replicationd ReplicationAPI.cpp(16705) [webguid] setGlobalReplicationPauseStatus() - User has paused the replication service

Now we'll enable DEBUG logging
- Stop process watcher (rm /var/DXi/processwatcher).
- Change INFO to DEBUG in log-common.conf and save the file.
- Restart the log server (service log4cplus-server restart).
- Restart replicationd, because that is the process using this logger.
In ReplicationAPI.cpp in util_getHostIdsForThisHost() a debug message entry on line 9401 shows:

9401 QLOG_DEBUG(Logging::getLogger(), "Setting strHostName: %s", strHostName.c_str());

Looking for this message in tsunami we find:

DEBUG - 08/28/13-11:32:37 - replicationd ReplicationAPI.cpp(9401) [replicationd] util_getHostIdsForThisHost() 02:15:20:517.569 - Setting strHostName: ryan2211source.ses.local

Log Entry Format

The format for most log entries that get written to tsunami.log is defined in log-server.conf as:

log4cplus.appender.ALL_APP.layout.ConversionPattern = %-6p - %D{%x-%H:%M:%S} - %c %F(%L) %m%n
- %-6p
  - %p is the logging level/severity
  - %-6p means print the logging level up to 6 characters
  - If you were to change %-6p to %-3p, for example, tsunami entries would start with DEB, WAR, ERR, etc.
- The hyphen after the log level is printed as is
- %D with the following variables in the squiggly brackets is the timestamp format
- Another hyphen
- %c is the name of the logger
  - This is the string supplied when the logger is defined
  - For example, the following line of code defines the logger as "replicationd":
    - qntm_log::logger repLog("replicationd");
- %F(%L)
  - %F is the name of the code file
  - (%L) is the line number in the code file
  - The parens are printed as is
- %m is the message and includes:
  - [caller] ( I'm not quite sure where this is defined yet, and am assuming that this is the caller that ran the code referenced in the log entry)
  - Function name
  - String supplied by the log statement
- %n adds a newline character
Let's break down a single log entry using an example from above:
- DEBUG - 08/28/13-11:32:37 - replicationd ReplicationAPI.cpp(9401) [replicationd] util_getHostIdsForThisHost() 02:15:20:517.569 - Setting strHostName: ryan2211source.ses.local
  - DEBUG
    - %-6p = DEBUG
  - -
  - 08/28/13-11:32:37
    - %D{%x-%H:%M:%S}
  - -
  - replicationd
    - %c
  - ReplicationAPI.cpp(9401)
    - %F(%L)
  - [replicationd] util_getHostIdsForThisHost() 02:15:20:517.569 - Setting strHostName: ryan2211source.ses.local
    - %m%n
    - message followed by newline
    - Broken down further:
      - [replicationd]
        
        caller
      - util_getHostIdsForThisHost()
        
        Function name
      - 02:15:20:517.569
        
        Not sure
      - Setting strHostName: ryan2211source.ses.local
        
        String supplied in QLOG_DEBUG(Logging::getLogger(), "Setting strHostName: %s", strHostName.c_str());
      - newline

Root Logger

The first logger defined is the root logger. One way to get debug for all loggers would be to set the root logger to DEBUG, then comment out all of the other loggers....or set them to INHERIT. Enabling DEBUG or TRACE on the root logger will add significant load, and probably should never be done on a customer system. In the lab, however, it is a great way to learn how things work short of reading the source code.

When Should I Enable DEBUG?

In many cases, the answer to this question is, "Whenever that the default logging levels don't give you enough information." With OST, for example, the INFO logging level almost always lacks enough information to understand what is going on. Another answer to this question is, "Whenever you can reproduce a failure/problem."

Most logging is written to be "minimalistic." When we in service discover bugs or issues, it typically won't have INFO/WARN/ERROR logs associated with it because...it's a bug. With this in mind, I think we can safely answer this question with the following answer:

Debug logging should be required for every escalation.

Having DEBUG enabled for a specific logger can save the higher-level support groups a significant amount of time. Without it, one must recreate the environment, read the code directly, spend hours searching bugzilla, and the like. With DEBUG enabled, we have a sort of translation or map telling us right where the code is, and what terms to use for searching bugzilla. Reading the DEBUG code is often sufficient to understand what is happening, without recreating the enviornment.

How Can I Know on Which Logger to Enable DEBUG?

This is self-explanatory if you know which process is having a problem. Sometimes you could have a replication problem that is related to the blockpool wrapper, so you might want DEBUG enabled on both of them. I would like to recommend that those of us in service create and maintain a list of loggers that pertain to a particular type of problem. For some problems, this is still guesswork. Enabling DEBUG or TRACE for the rootLogger on a lab DXi might be the best option to determine which loggers are needed.

Additional Resources:

Log4cplus website: http://log4cplus.sourceforge.net/