About This Document

...

ONAP prescribes conventions. The use of certain APIs and providers is recommended, but they are not mandatory. Most components log via EELF or SLF4J to a provider like Logback or Log4j.

Logging Specification Compliance

Logging Library Location and Use

What to Log

The purpose of logging is to capture diagnostic information.

An important aspect of this is analytics, which requires tracing of requests between components. In a large, distributed and scalable system such as ONAP this is critical to understanding behavior and performance. 

General 

It isn't the aim of this document to reiterate Best Practices, so advice here is general: 

• Use a logging facade such as SLF4J or EELF. 
• Write log messages in English.
• Write meaningful messages. Consider what will be useful to consumers of logger output. 
• Log at the appropriate level. Be aware of the volume of logs that will be produced.
• Safeguard the information in exceptions, and ensure it is never lost.
• Use errorcodes to characterise exceptions. 
• Log in a machine-readable format. See Conventions.
• Log for analytics as well as troubleshooting.

Others have written extensively on this: 

• http://www.masterzen.fr/2013/01/13/the-10-commandments-of-logging/
• https://www.loggly.com/blog/how-to-write-effective-logs-for-remote-logging/
• And so on.

Standard Attributes

These are attributes common to all log messages. They are either:

• Explicitly required by logging APIs:
  
  • Logger
  • Level
  • Message
  • Exception (note that exception is the only standard attribute that may routinely be empty).
• Implicitly derived by the logging provider:
  • Timestamp
  • Thread.

Which means you normally can't help but report them. 

See https://www.slf4j.org/api/org/slf4j/Logger.html and https://logback.qos.ch/manual/layouts.html#ClassicPatternLayout for their origins and use.

Logger Name

This indicates the name of the logger that logged the message.

In Java it is convention to name the logger after the class or package using that logger.

• In Java, report the class or package name.
• In Python, the class or source filename.

Most other languages will fit one of those patterns. 

Level

Severity, typically drawn from the enumeration {TRACE, DEBUG, INFO, WARN, ERROR}.

Think carefully about the information you report at each log level. The default log level is INFO.

Some loggers define non-standard levels, like FINE, FINER, WARNING, SEVERE, FATAL or CRITICAL. Use these judiciously, or avoid them.

Message

The free text payload of a log event. 

This is the most important item of information in most log messages. See General guidelines.

Internationalization

Diagnostic log messages generally do not need to be internationalized.

Parameterization

Parameterized messages allow serialization to be deferred until AFTER level threshold checks. This means the cost is never incurred for messages that won't be written. 

• Favor parameterized messages, especially for INFO and DEBUG logging.
• Perform expensive serialization in the #toString method of wrapper classes.

For example:

logger.debug("Relax - this won't hurt: {}", new ToStringWrapper(costlyToSerialize));

Exception

The error stacktrace, where applicable.

Log unabridged stacktraces upon error.

When rethrowing, ensure that frame information is not lost:

• By logging the original exception at the point where it was caught. 
• By setting the original exception as the cause when rethrowing.

Timestamp

Logged as an ISO8601 UTC datetime. Millisecond (or greater) precision is preferable.

For example:

2018-07-05T20:21:34.794Z

Offset timestamps are OK provided the offset is included. (In the above example, the "Z" is a shorthand indicating an offset of zero – UTC).

Thread

The name of the thread from which the log message was emitted.

Thread names don't necessarily convey useful information, and their reliability depends on the thread model implemented by different runtimes, but they are sometimes used in heuristic analysis.

Efficiency

There is tension between utility and efficiency. IO bandwidth is finite, and the cost of serialization can be significant, especially at higher diagnostic levels.

Methods and Line Numbers

Many loggers can use reflection to emit the originating (Java) method, and even individual line numbers.

This information is certainly useful, but very expensive. Most logging implementations recommend that this not be enabled in production.

Level Thresholds

Level indicates severity.

Logger output is typically filtered by logger and level. The default logging level is INFO, so particular consideration should be given to the efficiency of INFO-level logging.

When DEBUG-level logging is configured, it's probably for good reason, and a greater overhead is expected. Be aware that it's not unusual for DEBUG logging to be left enabled inadvertently, however.

WARN and ERROR-level messages are of higher value, and comparatively rare, so their cost is less of a concern.

Conditionals

A common pattern is to place conditionals around (expensive) serialization.

For example:

if (logger.isDebugEnabled()) {
    logger.debug("But this WILL hurt: " + costlyToSerialize);
}

Parameterized logging is preferable.

providers is recommended, but they are not mandatory. Most components log via EELF or SLF4J to a provider like Logback or Log4j.

Logging Specification Compliance

Logging Library Location and Use

What to Log

Context

MDCs

A Mapped Diagnostic Context (MDC) allows an arbitrary string-valued attribute to be attached to a Java thread via a ThreadLocal variable. The MDC's value is then emitted with each message logged by that thread. The set of MDCs associated with a log message is serialized as unordered name-value pairs (see Text Output).

...

• Must be set as early in invocation as possible. 
• Must be unset on exit. 
• keep in sync with https://wiki.acumos.org/display/OAM/Log+Standards

Logging

Via SLF4J:

import java.util.UUID;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
// ...
final Logger logger = LoggerFactory.getLogger(this.getClass());
MDC.put("SomeUUID", UUID.randomUUID().toString());
try {
    logger.info("This message will have a UUID-valued 'SomeUUID' MDC attached.");
    // ...
}
finally {
    MDC.clear();
}

...

Note there are 3 tabs (see p_mak in logback.xml) delimiting the MARKERS (ENTRY and EXIT) at the end of each line

<property name="p_mak" value="%replace(%replace(%marker){'\t', '\\\\t'}){'\n','\\\\n'}"/>

2018-07-05T20:21:34.794Z	http-nio-8080-exec-2	INFO	org.onap.demo.logging.ApplicationService	InstanceID=ede7dd52-91e8-45ce-9406-fbafd17a7d4c, RequestID=f9d8bb0f-4b4b-4700-9853-d3b79d861c5b, ServiceName=/logging-demo/rest/health/health, InvocationID=8f4c1f1d-5b32-4981-b658-e5992f28e6c8, InvokeTimestamp=2018-07-05T20:21:26.617Z, PartnerName=, ClientIPAddress=0:0:0:0:0:0:0:1, ServerFQDN=localhost			ENTRY	
2018-07-05T20:22:09.268Z	http-nio-8080-exec-2	INFO	org.onap.demo.logging.ApplicationService	ResponseCode=, InstanceID=ede7dd52-91e8-45ce-9406-fbafd17a7d4c, RequestID=f9d8bb0f-4b4b-4700-9853-d3b79d861c5b, ServiceName=/logging-demo/rest/health/health, ResponseDescription=, InvocationID=8f4c1f1d-5b32-4981-b658-e5992f28e6c8, Severity=, InvokeTimestamp=2018-07-05T20:21:26.617Z, PartnerName=, ClientIPAddress=0:0:0:0:0:0:0:1, ServerFQDN=localhost, StatusCode=			EXIT	

...

Logfiles should default to beneath /var/log, and beneath /var/log/ONAPonap in the case of core ONAP components:

/var/log/ONAPonap/<component>[/<subcomponent>]/*.log

Anything else written into /var/log/ONAP_EELF, if so, is it /var/log/ONAP_EELF or /var/log/onap_EELF?

For the duration of Beijing, logs  will be written to a separate directory, /var/log/ONAP_EELF:

expand on Casablanca differences, and adding as a config setting in OOM

/var/log/ONAP_EELF/<component>[/<subcomponent>]/*.log

...