20. Logging

AMPS supports logging to many different targets including the console, syslog, and files. Every error message within AMPS is uniquely identified and can be filtered out or explicitly included in the logger output. This chapter of the AMPS User Guide describes the AMPS logger configuration and the unique settings for each logging target.

Configuration

Logging within AMPS is enabled by adding a Logging section to the configuration. For example, the following would log all messages with an ‘info’ level or higher to the console:

<AMPSConfig>
    ...
    <Logging>

        <!-- The Logging section defines a single Target, which is used to log all messages
        to the stdout output. -->
        <Target>
            <Protocol>stdout</Protocol>

            <!-- States that only messages with a log level of info or greater will be output to
            the screen. -->
            <Level>info</Level>
        </Target>
    </Logging>
    ...
</AMPSConfig>

Log Messages

An AMPS log message is composed of the following:

  • Timestamp (eg: 2010-04-28T21:52:03.4766640-07:00)
  • AMPS thread identifier
  • Log Level (eg: info)
  • Error identifier (eg: 15-0008)
  • Log message

An example of a log line (it will appear on a single line within the log):

2011-11-23T14:49:38.3442510-08:00 [1] info: 00-0015 AMPS initialization completed (0 seconds).

Each log message has a unique identifier of the form TT-NNNN where TT is the component within AMPS which is reporting the message and NNNN the number that uniquely identifies that message within the module. Each logging target allows the direct exclusion and/or inclusion of error messages by identifier. For example, a log file which would include all messages from module 00 except for 00-0001 and 00-0004 would use the following configuration:

<Logging>
    <Target>
        <Protocol>stdout</Protocol>
        <IncludeErrors>00-0002</IncludeErrors>
        <ExcludeErrors>00-0001,00-0004,12-1.*</ExcludeErrors>
    </Target>
</Logging>

The above Logging configuration example, all log messages which are at or above the default log level of info will be emitted to the logging target of stdout. The configuration explicitly wants to see configuration messages where the error identifier matches 00-0002. Additionally, the messages which match 00-0001, 00-0004 will be excluded, along with any message which match the regular expression of 12-1.*.

Log Levels

AMPS has nine log levels of escalating severity. When configuring a logging target to capture messages for a specific log level, all log levels at or above that level are sent to the logging target. For example, if a logging target is configured to capture at the “error” level, then all messages at the “error”, “critical”, and “emergency” levels will be captured because “critical” and “emergency” are of a higher level. The following Table 20.1 contains a list of all the log levels within AMPS.

Level Description
developer

Information on the internal state of AMPS, typically used by the AMPS developers

Messages logged at this level do not indicate issues, but instead report the detailed state of the AMPS process.

trace

all inbound/outbound data

development and test instances are recommended to log at this level

debug

Obsolete. The AMPS server no longer logs messages at this level. Plugin modules that attempt to log messages at this level will log messages at info level instead.

instances that log at this level are recommended to use info level or trace level logging instead

stats statistics messages
info

general information messages

production applications are recommended to log at this level or more verbose

warning problems that AMPS tries to correct that are often harmless
error

events in which processing had to be aborted

events at this level often indicate that a client will receive incomplete or incorrect results (for example, a subscription could not be entered because an unknown option was provided)

critical events impacting major components of AMPS that if left uncorrected may cause a fatal event or message loss
emergency

a fatal event

AMPS will typically exit after logging an emergency-level event

none no logging, even in the case of a critical or fatal event

Table 20.1: Log Levels

Each logging target allows the specification of a Level attribute that will log all messages at the specified log level or with higher severity. The default Level is none which would log nothing. Optionally, each target also allows the selection of specific log levels with the Levels attribute. Within Levels, a comma separated list of levels will be additionally included.

For example, having a log of only trace messages may be useful for later playback, but since trace is at the lowest level in the severity hierarchy it would normally include all log messages. To only enable trace level, specify trace in the Levels setting as below:

<AMPSConfig>
    ...
    <Logging>
        <Target>
            <Protocol>gzip</Protocol>
            <FileName>traces.log.gz</FileName>
            <Levels>trace</Levels>
        </Target>
    </Logging>
    ...
</AMPSConfig>

Logging only trace and info messages to a file is demonstrated below:

<AMPSConfig>
    ...
    <Logging>
    <Target>
            <Protocol>file</Protocol>
            <FileName>traces-info.log</FileName>
            <Levels>trace,info</Levels>
        </Target>
    </Logging>
    ...
</AMPSConfig>

Logging trace, info messages in addition to levels of error and above (error, critical and emergency) is demonstrated below:

<Target>
    <Protocol>file</Protocol>
    <FileName>traces-error-info.log</FileName>
    <Level>error</Level>
    <Levels>trace,info</Levels>
</Target>

Logging to a File

To log to a file, declare a logging target with a protocol value of file. Beyond the standard Level, Levels, IncludeErrors, and ExcludeErrors settings available on every logging target, file targets also permit the selection of a FileName mask and RotationThreshold.

Selecting a Filename

The FileName attribute is a mask which is used to construct a directory and file name location for the log file. AMPS will resolve the file name mask using the symbols in Table 20.2. For example, if a file name is masked as:

%Y-%m-%dT%H:%M:%S.log

...then AMPS would create a log file in the current working directory with a timestamp of the form: 2012-02-23T12:59:59.log.

If a RotationThreshold is specified in the configuration of the same log file, the next log file created will be named based on the current system time, not on the time that the previous log file was generated. Using the previous log file as an example, if the first rotation was to occur 10 minutes after the creation of the log file, then that file would be named 2012-02-23T13:09:59.log.

Log files which need a monotonically increasing counter when log rotation is enabled can use the %n mask to provide this functionality. If a file is masked as:

localhost-amps-%n.log

Then the first instance of that file would be created in the current working directory with a name of localhost-amps-00000.log. After the first log rotation, a log file would be created in the same directory named localhost-amps-00001.log.

Log file rotation is discussed in greater detail in Log File Rotation.

Mask Definition
%Y Year
%m Month
%d Day
%H Hour
%M Minute
%S Second
%n Iterator which starts at 00000 when AMPS is first started and increments each time a RotationThreshold size is reached on the log file.

Table 20.2: Log Filename Masks

Log File Rotation

Log files can be “rotated” by specifying a valid threshold in the RotationThreshold attribute. Values for this attribute have units of bytes unless another unit is specified as a suffix to the number. The valid unit suffixes are:

Unit Suffix Base Unit Examples
no suffix bytes “1000000” is 1 million bytes
k or K thousands of bytes “50k” is 50 thousand bytes
m or M millions of bytes “10M” is 10 million bytes
g or G billions of bytes “2G” is 2 billion bytes
t or T trillions of bytes “0.5T” is 500 billion bytes

Table 20.3: Log File Rotation Units

Tip

When using log rotation, if the next filename is the same as an existing file, the file will be truncated before logging continues. For example, if “amps.log” is used as the FileName mask and a RotationThreshold is specified, then the second rotation of the file will overwrite the first rotation. If it is desirable to keep all logging history, then it is recommended that either a timestamp or the %n rotation count be used within the FileName mask when enabling log rotation.

Examples

The following logging target definition would place a log file with a name constructed from the timestamp and current log rotation number in the ./logs subdirectory. The first log would have a name similar to ./logs/20121223125959-00000.log and would store up to 2GB before creating the next log file named ./logs/201212240232-00001.log.

<AMPSConfig>
    ...
    <Logging>
        <Target>
            <Protocol>file</Protocol>
            <Level>info</Level>
            <FileName>./logs/%Y%m%d%H%M%S-%n.log</FileName>
            <RotationThreshold>2G</RotationThreshold>
        </Target>
    </Logging>
    ...
</AMPSConfig>

This next example will create a single log named amps.log which will be appended to during each logging event. If amps.log contains data when AMPS starts, that data will be preserved and new log messages will be appended to the file.

<AMPSConfig>
    ...
    <Logging>
        <Target>
        <Protocol>file</Protocol>
        <Level>info</Level>
        <FileName>amps.log</FileName>
        </Target>
    </Logging>
    ...
</AMPSConfig>

Logging to a Compressed File

AMPS supports logging to compressed files as well. This is useful when trying to maintain a smaller logging footprint. Compressed file logging targets are the same as regular file targets except for the following:

  • the Protocol value is gzip instead of file;
  • the log file is written with gzip compression;
  • the RotationThreshold is metered off of the uncompressed log messages;
  • makes a trade off between a small increase in CPU utilization for a potentially large savings in logging footprint.

Example

The following logging target definition would place a log file with a name constructed from the timestamp and current log rotation number in the ./logs subdirectory. The first log would have a name similar to ./logs/20121223125959-0.log.gz and would store up to 2GB of uncompressed log messages before creating the next log file named ./logs/201212240232-1.log.gz.

<AMPSConfig>
    ...
    <Logging>
        <Target>
            <Protocol>gzip</Protocol>
            <Level>info</Level>
            <FileName>./logs/%Y%m%d%H%M%S-%n.log.gz</FileName>
            <RotationThreshold>2G</RotationThreshold>
        </Target>
    </Logging>
    ...
</AMPSConfig>

Logging to the Console

The console logging target instructs AMPS to log certain messages to the console. Both the standard output and standard error streams are supported. To select standard out use a Protocol setting of stdout. Likewise, for standard error use a Protocol of stderr.

Example

Below is an example of a console logger that logs all messages at the info or warning level to standard out and all messages at the error level or higher to standard error (which includes error, critical and emergency levels).

<AMPSConfig>
    ...
    <Logging>
        <Target>
            <Protocol>stdout</Protocol>
            <Levels>info,warning</Levels>
        </Target>
        <Target>
            <Protocol>stderr</Protocol>
            <Level>error</Level>
        </Target>
    </Logging>
    ...
</AMPSConfig>

Logging to Syslog

AMPS can also log messages to the host’s syslog mechanism. To use the syslog logging target, use a Protocol of syslog in the logging target definition.

The host’s syslog mechanism allows a logger to specify an identifier on the message. This identifier is set through the Ident property and defaults to the AMPS instance name (see AMPS Configuration Reference Guide for configuration of the AMPS instance name.)

The syslog logging target can be further configured by setting the Options parameter to a comma-delimited list of syslog flags. The recognized syslog flags are:

Level Description
LOG_CONS Write directly to system console if there is an error while sending to system logger.
LOG_NDELAY Open the connection immediately (normally, the connection is opened when the first message is logged).
LOG_NOWAIT No effect on Linux platforms.
LOG_ODELAY The converse of LOG_NDELAY; opening of the connection is delayed until syslog() is called. (This is the default, and need not be specified.)
LOG_PERROR Print to standard error as well.
LOG_PID Include PID with each message.

Table 20.4: Logging Options Available for SYSLOG Configuration

Tip

AMPS already includes the process identifier (PID) with every message it logs, however, it is a good practice to set the LOG_PID flag so that downstream syslog analysis tools will find the PID where they expect it.

The Facility parameter can be used to set the syslog “facility”. Valid options are: LOG_USER (the default), LOG_LOCAL0, LOG_LOCAL1, LOG_LOCAL2, LOG_LOCAL3, LOG_LOCAL4, LOG_LOCAL5, LOG_LOCAL6, or LOG_LOCAL7.

Finally, AMPS and the syslog do not have a perfect mapping between their respective log severity levels. AMPS uses the following table to convert the AMPS log level into one appropriate for the syslog:

AMPS Severity Syslog Severity
none LOG_DEBUG
developer LOG_DEBUG
trace LOG_DEBUG
debug LOG_DEBUG
stats LOG_INFO
info LOG_INFO
warning LOG_WARNING
error LOG_ERR
critical LOG_CRIT
emergency LOG_EMERG

Table 20.5: Comparison of AMPS Log Severity to Syslog Severity

Example

Below is an example of a syslog logging target that logs all messages at the critical severity level or higher and additionally the log messages matching 30-0001 to the syslog.

<AMPSConfig>
    ...
    <Logging>
        <Target>
            <Protocol>syslog</Protocol>
            <Level>critical</Level>
            <IncludeErrors>30-0000</IncludeErrors>
            <Ident>\amps dma</Ident>
            <Options>LOG_CONS,LOG_NDELAY,LOG_PID</Options>
            <Facility>LOG_USER</Facility>
        </Target>
    </Logging>
    ...
</AMPSConfig>

Error Categories

In the AMPS log messages, the error identifier consists of an error category, followed by a hyphen, followed by an error identifier. The error categories cover the different modules and features of AMPS, and can be helpful in diagnostics and troubleshooting by providing some context about where a message is being logged from. A list of the error categories found in AMPS are listed in Table 20.6.

AMPS Code Component
00 AMPS Startup
01 General
02 Message Processing
03 Expiration
04 Publish Engine
05 Statistics
06 Metadata
07 Client
08 Regex
09 ID Generator
0A Diff Merge
0B Out of Focus processing
0C View
0D Message Data Cache
0E Conflated Topic
0F Message Processor Manager
11 Connectivity
12 Trace In - for inbound messages
13 Datasource
14 Subscription Manager
15 SOW
16 Query
17 Trace Out - for outbound messages
18 Parser
19 Administration Console
1A Evaluation Engine
1B SQLite
1C Meta Data Manager
1D Transaction Log Monitor
1E Replication
1F Client Session
20 Global Heartbeat
21 Transaction Replay
22 TX Completion
23 Bookmark Subscription
24 Thread Monitor
25 Authorization
26 SOW cache
28 Memory cache
29 Plug-in modules (including AMPS features implemented as modules)
2A Message pipeline
2B Module manager
2C File management
2D NUMA module
2F SOW update broadcaster
30 AMPS internal utilities
31 AMPS queues
70 AMPS networking
FF Shutdown

Table 20.6: AMPS Error Categories

Using amps-grep to Find Information in Logs

The AMPS logs contain a record of events in the instance. Log messages are intended to be read as a part of that sequence of events. While an individual message is useful for showing that a particular event happened, the other messages in the log will show what sequence of events lead up to that event and what the results of that event were.

At the same time, an active AMPS instance with dozens or hundreds of active clients generates a high volume of events, which can make it difficult to locate and correlate the events that are relevant to a specific problem. To help with this, the AMPS distribution contains the amps-grep tool to make it easy to find information in the logs.

This section presents some of the most useful techniques for locating information in the logs using amps-grep.

Finding Information for a Specific Client

When troubleshooting problems with a specific client (or connection), it’s often helpful to be able to see the full sequence of events for that client. For example, if AMPS is returning an invalid options message to a client, finding the command that the client is sending to AMPS and the detailed messages that AMPS logs in response can be very helpful in understanding the details of the error.

To find information about a specific client, use the following general pattern:

$ amps-grep client_name log_files > out.txt 

The amps-grep command extracts every event that contains the client name from the log files, and then the Linux shell writes those events to the out.txt file. Because the amps-grep tool is aware of the structure of multi-line AMPS event records, it captures the full event message, not just the individual lines that contain the name of the client.

For example, if the client has a client name of queue-processor-compute-host-39, and the logs are stored in files with the suffix .log, the command to extract the events with that client name would be along the lines of:

$ amps-grep 'queue-processor-compute-host-39' *.log > out.txt

This command will write every event message that contains a reference to the client queue-processor-compute-host-39 to the out.txt file.

Finding Information for a Specific Thread

Another situation where amps-grep can be useful is when it is important to get information about a specific thread in AMPS.

For example, in a situation where AMPS has produced a minidump, it is typically more useful to see the activity on the thread that produced the dump than it is to see the activity of other threads near the time that the minidump was produced.

To track the sequence of events for a thread that produces a minidump, the first step is to find the AMPS identifier for the thread. This is the identifier used in the event log messages, which is different than the operating system assigned identifier for the thread, and then use that identifier to extract messages form the log.

For example, given a minidump message like the following

2020-04-25T07:27:59.1355850-07:00 [6] critical: 01-0022 AMPS has
detected that it may not be running correctly and wrote a minidump to:
/tmp/1516e4d1-8bca-b14b-17853753-45dba87b.dmp

AMPS has assigned thread ID 6 to this thread. For convenience in searching, AMPS always puts the thread ID in brackets at the beginning of the message (since 6, by itself, is so common in the logs as to not be useful).

Extracting every message recorded by thread id 6 in the log can be done with a command like the following:

$ amps-grep ' [6] ' *.log > out.txt

With this command line, amps-grep locates all messages for that thread ID, and the Linux shell writes the results to the out.txt file.

Tips for Using amps-grep

When using amps-grep, there are a few things to be aware of:

  1. Unlike regular grep, by default amps-grep uses exact matching rather than regular expression matching. To use a regular expression, provide the -E option to amps-grep.

  2. If you are searching multiple files and piping the output of one amps-grep command to another amps-grep command, use the -h flag to the first amps-grep to suppress the file name on matching lines. If you do not provide -h, the presence of the file name can interfere with amps-grep correctly identifying the start and end of each AMPS log message.

  3. If you want to find more than one search term, you can use the -e flag to specify multiple search terms, for example:

    $ amps-grep -e 'error' -e 'warning' *.log
    

    Although it is possible to use a regular expression for a search like this, it is not necessary to do so.

  4. The amps-grep utility provides a usage message with more details on the available options and usage.

Looking Up Errors with ampserr

In the $AMPSDIR/bin directory is the ampserr utility. Running this utility is useful for getting detailed information and messages about specific AMPS errors observed in the log files.

The AMPS Utilities User Guide contains more information on using the ampserr utility and other debugging tools.