Home
The Foundation Logging API is an extension of the standard log4j library exposed through SLF4J API. Besides complementing some core log4j features (e.g. size based log file rolling), it also introduces Structured Logging in support of log based analytics use cases.
The Foundation Logging should be used in ALL Foundation java components.
<groupId>com.cisco.oss.foundation</groupId>
<artifcatId>logging-api</artifcatId>
<version>Latest Version</version>
<groupId>com.cisco.oss.foundation</groupId>
<artifcatId>logging-log4j</artifcatId>
<version>Latest Version</version>
All releases are available in public maven repo.
Following is a high level capture of the overall design of Foundation Logging:
- Users are expected to use the SLF4J API
- Below that you can (optionally) use the Markers for Structured Logging (see below more info)
- Foundation logging adds a binding (on logging-log4j lib) between SLF4J and log4j
- Log4j Implementation allows the following main features:
- Support writing to a log file (or any other output) asynchronously.
- Verify all logs are in UTC timezone. This improves greatly the ability to compare logs from different nodes from (possibly) different sites.
- Use common Log Patterns - I.e. the time-stamp format, logger name, thread name etc.
- Add support for Archiving
- Allow rolling to a new file every time your process is restarted.
- Allow rolling to a new file based on a specific time of day (e.g. Midnight).
- Allow rolling to a new file based on file size OR based on History (i.e. every 5 days - regardless of file size).
Following is a simple, developer oriented, user guide on how to use Foundation Logging.
As we currently only support log4j, you must add the log4j configuration file to your classpath. Following are some tips and tricks on how to tweak the logging library to your needs.
Note: logging-log4j is based on log4j 1.x. and logging-log4j2 is based on log4j 2.x. Please use the below links for specific configuration instructions for each version.
Configuration log4j 1.x support
Configuration log4j 2.x support
To understand the notion of "structured" logging, it's useful to consider the current situation. Take a look at this snippet.
int transactionId = 6492;
String actionType = "CreateHousehold";
String householdType = "Multi";
int deviceCount = 10;
logger.Log( "Transaction " + transactionId + " of type " + actionType + "( " + householdType + ") " + " was received for creation of " + deviceCount + " devices");
What is happening here? A component is logging information about a request to create a certain type of household. So far so good. Except that once in the log file, all the data points themselves - transactionId, actionType, householdType and deviceCount have essentially been "deconstructed" into a string. To reestablish these values - let's say for the purpose of BI analysis or log file playback, a process of parsing will be necessary. Parsing is expensive (developer time) and error prone.
At the conceptual level there is a flaw here. The component 'knows' the values for transactionId, actionType, householdType and deviceCount, but it actively deconstructs them in the logging method, for lack of a better option.
Structured Logging is that better option. It will allow component developers to use a standard based mechanism to log messages, without having to deconstruct the data points in the process. Consider the following pseudo code:
class HouseHouseholdTransaction
{
int transactionId;
int actionType;
String householdType;
int deviceCount;
}
logger.info( new HouseHouseholdTransaction( 6492,"CreateHousehold", "Multi", 10),"");
A configuration/resource file could define a pattern for the human readable log file, something like:
messagetype.HouseHouseholdTransaction.format = "Transaction $transactionId of type $actionType ( $householdType ) was received for creation of $deviceCount $devices"
Because the data points of HouseHouseholdTransaction are available to Foundation Logging infrastructure, it’s now possible to implement additional appenders that can work with ‘ HouseHouseholdTransaction ’ directly and do all types of interesting things in the area of playback and BI.
In summary, 'Structured Logging' is a mechanism, based on standard logging API, to allow components to maintain a log message's data points in structured fashion, to provide visibility and control for logging to human readable files, BI data files or playback files.
The current implementation is based on the popular [http://www.slf4j.org/ slf4j](http://www.slf4j.org/ slf4j "wikilink") library. Slf4j allows users to code their logging against a common API which can in turn be pointed to a large variety of implementations (log4j, java util logging, commons-logging to name a few).
One of the basic concepts in slf4j is the notion of a [http://slf4j.org/api/org/slf4j/Marker.html Marker](http://slf4j.org/api/org/slf4j/Marker.html Marker "wikilink").
Markers allow us to enable users to log their logs, that are targeted to an external consumer (as mentioned above), using markers themselves to enrich the log event with log event specific data which is not part of the regular log message or payload (e.g. source host in case of remote request handler or correlation id etc.).
This section describes the solution in depth and will answer some commonly asked questions.
To use the Marker API you will have to use the slf4j API. Regardless, we expect users to use the fl4j API which will enable switch to another slf4j binding seamlessly to the applicative code.
When using Foundation Logging Markers to log transaction activity, you should always use the same Marker type for all steps in the transaction. Thus, the Marker type should have some type of 'state' field that describes the current transaction phage (examples: START, SUCCESS, FAILURE). As per explanation below, it's possible to define multiple human readable output formats for the same Marker, depending on its state.
If you use a Logger and pass in a Marker and you want the output in a human readable format, you should follow the following guidelines.
First and foremost First and foremost - your marker should extend AbstractFoundationLoggingMarker.
User Field Annotation Any field you want to expose and use in an external pattern should be annotated using @UserField.
The UserField annotation can, optionally, be set with 2 attributes:
- suppressNull - set to true if you wish a field to be omitted when its value is not set. default is false meaning if a field in the marker is not filled, a "null" string will be used.
- description - for future use, you may add description of this field.
Marker fields annotated by @UserField are accesible from the pattern layout by using the %u{fieldName} syntax.
For example:
My default format for %u{sourceId} and %u{sourceType}
In the above example, in runtime, the actual values of "sourceId" and "sourceType" fields will be inserted in their designated place holders.
Defining Layout Annotations
The recommended way to define Human Readable Layout formats is by using the following annotations:
- @DefaultFormat - This is a must in any Marker. You specify here the default human readable format of this Marker. See example below.
- @ConditionalFormats - Optionally You can define a list of @ConditionalFormat under a single @ConditionalFormats annotation. Each @ConditionalFormat contains a format String and a list of @FieldCriterion annotations. Each @FieldCriterion contains a name and a value.
How Does It Work Upon Component start-up, Foundation Logging scans the classpath and finds all markers that have the above annotations. Once found, these annotations are parse ONCE per marker class and a formatter class is generated in Runtime. This class contains the logic on which format is to be used cased on the marker state.
The logic of the annotations is as follows: Between @FieldCriterion there is an AND relationship. Between the @ConditionalFormat annotations there is a OR relationship. you can see the generated class source in the log file if you turn on TRACE level debug on the "log4j.logger.com.cisco.oss.foudnation.logging" logger in your log4j.properties.
Marker Example
package com.cisco.oss.foundation.logging.structured.test;
import com.cisco.oss.foundation.logging.structured.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@DefaultFormat(TransactionMarker.DEFAULT_FORMAT)
@ConditionalFormats({
@ConditionalFormat( format=TransactionMarker.COND_FORMAT_1,
criteria={
@FieldCriterion(name="sourceId", value="sourceId1"),
@FieldCriterion(name="sourceType", value="sourceType1")}),
@ConditionalFormat( format=TransactionMarker.COND_FORMAT_2,
criteria={
@FieldCriterion(name="sourceId", value="sourceId2"),
@FieldCriterion(name="sourceType", value="sourceType2")
}
),
@ConditionalFormat( format=TransactionMarker.COND_FORMAT_3,
criteria={
@FieldCriterion(name="sourceId", value="sourceId3"),
@FieldCriterion(name="sourceType", value="sourceType3")
}
)
})
public class TransactionMarker extends BaseTransactionLoggingMarker {
Logger LOGGER = LoggerFactory.getLogger(TransactionMarker.class);
private static final long serialVersionUID = 9161271890930513129L;
public static final String DEFAULT_FORMAT = "my default uncoditioned format!!!";
public static final String COND_FORMAT_1 = "my human readbale format 1";
public static final String COND_FORMAT_2 = "my human readbale format 2";
public static final String COND_FORMAT_3 = "my human readbale format 3";
public TransactionMarker(String sessionId) {
this.sessionId = sessionId;
}
@UserField(suppressNull = true)
private FoundationLoggingEventType eventType;
@UserField
private FoundationLoggingTransMsgType transMsgType;
@UserField
private String sessionId;
@UserField
private String sourceId;
@UserField
private String sourceType;
@UserField
private String destinationId;
@UserField
private String destinationType;
@UserField
private String messagePayload;
public TransactionMarker setEventType(FoundationLoggingEventType eventType) {
this.eventType = eventType;
return this;
}
public TransactionMarker setTransMsgType(FoundationLoggingTransMsgType transMsgType) {
this.transMsgType = transMsgType;
return this;
}
public TransactionMarker setSessionId(String sessionId) {
this.sessionId = sessionId;
return this;
}
public TransactionMarker setSourceId(String sourceId) {
this.sourceId = sourceId;
return this;
}
public TransactionMarker setSourceType(String sourceType) {
this.sourceType = sourceType;
return this;
}
public TransactionMarker setDestinationId(String destinationId) {
this.destinationId = destinationId;
return this;
}
public TransactionMarker setDestinationType(String destinationType) {
this.destinationType = destinationType;
return this;
}
public TransactionMarker setMessagePayload(String messagePayload) {
this.messagePayload = messagePayload;
return this;
}
public static long getSerialversionuid() {
return serialVersionUID;
}
public static String getDefaultFormat() {
return DEFAULT_FORMAT;
}
public static String getCondFormat1() {
return COND_FORMAT_1;
}
public static String getCondFormat2() {
return COND_FORMAT_2;
}
public static String getCondFormat3() {
return COND_FORMAT_3;
}
public FoundationLoggingEventType getEventType() {
return eventType;
}
public FoundationLoggingTransMsgType getTransMsgType() {
return transMsgType;
}
public String getSessionId() {
return sessionId;
}
public String getSourceId() {
return sourceId;
}
public String getSourceType() {
return sourceType;
}
public String getDestinationId() {
return destinationId;
}
public String getDestinationType() {
return destinationType;
}
public String getMessagePayload() {
return messagePayload;
}
}
In the above example the generated formatter class will check if getSourceId() is equal to "sourceId1" AND getSourceType() is equal to "sourceType1" - if yes - COND_FORMAT_1 will be used.
If NOT, formatter class will check if getSourceId() is equal to "sourceId2" AND getSourceType() is equal to "sourceType2" - if yes - COND_FORMAT_2 will be used.
If NOT, formatter class will check if getSourceId() is equal to "sourceId3" AND getSourceType() is equal to "sourceType3" - if yes - COND_FORMAT_3 will be used.
If NOT - DEFAULT_FORMAT will be used.
Defining Layout Overrides Via External XML Foundation Logging, when started, will search the class path for a file named: "messageFormat.xml". This is an optional file that allows users to alter the format strings returned by the annotations and even change the conditions internal logic.
The schema file for this xml is located [http://ch-infra.il.nds.com/cabResources/messageFormat.xsd here](http://ch-infra.il.nds.com/cabResources/messageFormat.xsd here "wikilink")
The xml file has an a advantage over the annotations that it supports different formats for different appenders.
Here is an XML example. Note that the minimum required elements and attributes are:
- One "defaultAppender" element (not more than one). Minimal attribute
is:
- defaultFormat - - the default format of this marker for the default appender - i.e. any appender used that isn't detailed in an "appender" element below.
- Zero or more "appender" elements. Minimal attributes per appender
element are:
- id - the fully qualified marker class name
- defaultFormat - the default format of this marker.
All other elements and attributes are optional and follow the same logic described above for the annotations.
<markers xsi:noNamespaceSchemaLocation="http://ch-infra.il.nds.com/cabResources/messageFormat.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
<marker id="com.cisco.oss.foundation.logging.structured.test.TransactionMarker">
<defaultAppender defaultFormat="My default format for %u{sourceId} and %u{sourceType} and %u{base}">
<criteria>
<criterion format="my conditional format 1 from xml">
<field name="sourceId" equals="sourceId1" />
<field name="sourceType" equals="sourceType1" />
</criterion>
<criterion format="my conditional format 2 from xml">
<field name="sourceId" equals="sourceId2" />
<field name="sourceType" equals="sourceType2" />
</criterion>
<criterion format="my conditional format 3 from xml">
<field name="sourceId" equals="sourceId3" />
<field name="sourceType" equals="sourceType3" />
</criterion>
<criterion format="my conditional format 4 from xml">
<field name="sourceId" equals="sourceId3" />
<field name="sourceType" equals="sourceType4" />
</criterion>
</criteria>
</defaultAppender>
<appender id="logfile" defaultFormat="My default format for %u{sourceId} and %u{sourceType}">
<criteria>
<criterion format="my conditional format 1 from xml">
<field name="sourceId" equals="sourceId1" />
<field name="sourceType" equals="sourceType1" />
</criterion>
<criterion format="my conditional format 2 from xml">
<field name="sourceId" equals="sourceId2" />
<field name="sourceType" equals="sourceType2" />
</criterion>
</criteria>
</appender>
<appender id="anotherfile" defaultFormat="My default format for %u{sourceId} and %u{sourceType} and %u{base}">
<criteria>
<criterion format="my conditional format 1 from xml - something else">
<field name="sourceId" equals="sourceId1" />
<field name="sourceType" equals="sourceType1" />
</criterion>
</criteria>
</appender>
<appender id="biFile" defaultFormat="My default format for %u{sourceId} and %u{sourceType}" />
</marker>
<marker id="TransactionMarker3">
<defaultAppender defaultFormat="My default format for %u{sourceId} and %u{sourceType}" />
<appender id="logfile" defaultFormat="My default format for %u{sourceId} and %u{sourceType}">
<criteria>
<criterion format=" my conditional format 1 from xml ">
<field name="sourceId" equals="sourceId1" />
<field name="sourceType" equals="sourceType1" />
</criterion>
<criterion format="my conditional format 2 from xml">
<field name="sourceId" equals="sourceId2" />
<field name="sourceType" equals="sourceType2" />
</criterion>
</criteria>
</appender>
<appender id="anotherfile" defaultFormat="My default format for %u{sourceId} and %u{sourceType}">
<criteria>
<criterion format="my conditional format 1 from xml">
<field name="sourceId" equals="sourceId1" />
<field name="sourceType" equals="sourceType1" />
</criterion>
</criteria>
</appender>
<appender id="biFile" defaultFormat="My default format for %u{sourceId} and %u{sourceType}" />
</marker>
<marker id="com.cisco.oss.foundation.logging.structured.test.TransactionMarker2">
<defaultAppender defaultFormat="My default format for %u{sourceId} and %u{sourceType}" />
<appender id="logfile" defaultFormat="My default format for %u{sourceId} and %u{sourceType}">
<criteria>
<criterion format=" my conditional format 1 from xml ">
<field name="sourceId" equals="sourceId1" />
<field name="sourceType" equals="sourceType1" />
</criterion>
<criterion format="my conditional format 2 from xml">
<field name="sourceId" equals="sourceId2" />
<field name="sourceType" equals="sourceType2" />
</criterion>
</criteria>
</appender>
<appender id="anotherfile" defaultFormat="My default format for %u{sourceId} and %u{sourceType}">
<criteria>
<criterion format="my conditional format 1 from xml">
<field name="sourceId" equals="sourceId1" />
<field name="sourceType" equals="sourceType1" />
</criterion>
</criteria>
</appender>
<appender id="biFile" defaultFormat="My default format for %u{sourceId} and %u{sourceType}" />
</marker>
</markers>
The above guideline has omitted the log/audit guideline you may remember from Ex-NDS Wiki as it is currently under review.
Q. When do files get “rolled”? -- e.g. when does one file close and a new one opens?
A. Either on midnight, OR when max file size is reached, OR when component is restarted.
Q. Where are the default parameters controlled?
A. They are hard coded inside Foundation logging library -- but can (optionally) be overridden in log4j.properties.
Q. Does archiving flag control when log files are rolled or deleted?
A. It only controls whether to archive a file once a new one was created. It by no means deleted files or does anything other than archive files.
Q. We’ve seen log messages get deleted when archiving is turned on. Why?
A. there was a bug prior to iteration 35 that rolling during archive caused messages to get lost. Post version 3.35.0-1 (inclusive) this is resolved.
Q. We’ve seen that upon rolling to a new file -- only last 10 files are kept. Is this expected?
A. There was a bug in Foundation logging that mandated override of MaxFileRollCount=100 to overcome this issue. As of version 3.35.0-1 -- this bug was resolved and you can safely rely on the defaults that come with the library itself.