Make sense of logs

There are multiple reasons why we may need to capture the application activity.

• Recording unusual circumstances or errors that may be happening in the program
• Getting the info about what’s going in the application

Logging Components

The Java logging API consists of three core components:

• Loggers are responsible for capturing events (called LogRecords) and passing them to the appropriate Appender.
• Appenders (also called Handlers in some logging frameworks) are responsible for recording log events to a destination. Appenders use Layouts to format events before sending them to an output.
• Layouts (also called Formatters in some logging frameworks) are responsible for converting and formatting the data in a log event. Layouts determine how the data looks when it appears in a log entry.

When your application makes a logging call, the Logger records the event in a LogRecord and forwards it to the appropriate Appender. The Appender then formats the record using a Layout before sending it a destination such as a console, a file, or another application. Additionally, you can use one or more Filters to specify which Appenders should be used for which events. Filters aren’t required, but they give you greater control over the flow of your log messages.

What are the various log levels in java?

The details which can be obtained from the logs can vary. Sometimes, we may want a lot of details regarding the issue, or sometimes some light information only.
Like when the application is under development and is undergoing the testing phase, we may need to capture a lot of details.
But when the application is running on production then we need only a certain kind of log that can be helpful to identify the problem in the Application like (Warning or error level).

Level	Description
ALL	This has the lowest possible rank and is intended to turn on all logging.
TRACE	It is similar to DEBUG but more detailed finer-grained informational events than.(ex: data model updated)
DEBUG	It is intended for such fine-grained informational events that could be useful in debugging an issue.(ex: method execution started, the response received from search service)
INFO	Designates informational messages that highlight the progress of the application at coarse-grained level.  And this should contain only those messages that describe what is happening in the application. (ex: profile uploaded, mail sent successfully)
WARN	It Designates potentially harmful situations. This is best used for temporary problems or unexpected behavior that does not significantly hamper the functioning of the application. (ex:  failed user login)
ERROR	Designates error events that might still allow the application to continue running. This should contain technical issues that need to be resolved for the proper functioning of the system (ex: couldn’t connect to the database)
FATAL	Designates very severe error events and should be reserved for errors that cause the application to crash or fail to start.This level Indicates some serious failure.(ex: JVM out of memory)
OFF	The highest possible rank and is intended to turn off logging.

TRACE can be customized further depending on the information we want.

FINE	General developer info
FINER	Detailed developer info
FINEST	Specialized Developer Info

Fine Finer and Finest provide tracing information. When what is happening/ has happened in our application.

FINE displays the most important messages out of these.

FINER outputs a detailed tracing message and may include logging calls regarding method entering, exiting, throwing exceptions.

FINEST provides a highly detailed tracing message.

How do Levels Works?

A log request of level suppose “p” in a logger with level “q” is enabled if p >= q. This rule is at the heart of log4j. It assumes that levels are ordered. For the standard levels, we have

ALL < TRACE < DEBUG < INFO < WARN < ERROR < FATAL < OFF.

import org.apache.log4j.*;

public class LogClass {
   private static org.apache.log4j.Logger log = Logger.getLogger(LogClass.class);
   
   public static void main(String[] args) {
      log.setLevel(Level.WARN);

      log.trace("Trace Message!");
      log.debug("Debug Message!");
      log.info("Info Message!");
      log.warn("Warn Message!");
      log.error("Error Message!");
      log.fatal("Fatal Message!");
   }
}

When you compile and run the LogClass program, it would generate the following result −

Warn Message!
Error Message!
Fatal Message!

Appenders or handlers:

Appenders listen for messages at or above a specified minimum severity level. The Appender takes the message it is passed and posts it appropriately. Message dispositions include:

• Display on the console
• Write to a plain log file
• Distribute via Kafka messaging service
• Append to a database table
• Send via email

Logback.xml:
You can choose the appenders according to the need for each profile (dev/test/staging/prod)

<root level="debug">
		<if
			condition='property("spring.profiles.active").equalsIgnoreCase("prod") || property("centralized.logs.enabled").equalsIgnoreCase("true")'>
			<then>
				<appender-ref ref="kafkaAppender" />
			</then>
			<else>
				<appender-ref ref="errorAppender" />
			</else>
		</if>
		<appender-ref ref="consoleAppender" />
		<appender-ref ref="infoAppender" />
		<appender-ref ref="debugAppender" />
	    <appender-ref ref="errorAppender" />
	</root>

Kafka Appender:

<!-- This is the kafkaAppender -->
	<appender name="kafkaAppender" class="com.github.danielwegener.logback.kafka.KafkaAppender">
		<!-- This is the default encoder that encodes every log message to an utf8-encoded 
			string -->
		<encoder>
				<pattern>${KAFKA_LOG_PATTERN}</pattern>
		</encoder>
		<topic>central-services-logs</topic>
		<keyingStrategy
			class="com.github.danielwegener.logback.kafka.keying.NoKeyKeyingStrategy" />
		<deliveryStrategy class="com.github.danielwegener.logback.kafka.delivery.AsynchronousDeliveryStrategy" />

		<!-- each <producerConfig> translates to regular kafka-client config (format: 
			key=value) -->
		<!-- producer configs are documented here: https://kafka.apache.org/documentation.html#newproducerconfigs -->
		<!-- bootstrap.servers is the only mandatory producerConfig -->
		<producerConfig>bootstrap.servers=kafka.logs.resdex.com:10092
		</producerConfig>
		<!-- wait for leader broker to ack the reception of a batch. -->
		<producerConfig>acks=1</producerConfig>
		<!-- wait up to 1000ms and collect log messages before sending them as 
			a batch -->
		<producerConfig>linger.ms=1000</producerConfig>
		<producerConfig>batch.size=10</producerConfig>
		<!-- define a client-id that you use to identify yourself against the kafka 
			broker -->
		<producerConfig>client.id=${serverName:-${HOSTNAME}}-${CONTEXT_NAME}-logback-appender
		</producerConfig>

		<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
			<level>INFO</level>
		</filter>

		<!-- this is the fallback appender if kafka is not available. -->
		<appender-ref ref="errorAppender" />
		<appender-ref ref="infoAppender" />
</appender>

Console Appender:

    <appender name="consoleAppender"
		class="ch.qos.logback.core.ConsoleAppender">
		<encoder>
			<pattern>${CONSOLE_LOG_PATTERN}</pattern>
		</encoder>
		<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
			<level>DEBUG</level>
		</filter>
	</appender>

Formatters, Layouts or renderers:

A Formatter is an object that formats a given object. Mostly this consists of taking the binary object and converting it to a string representation. Each framework defines a default output format that can be overridden if desired.

<!-- Define logging pattern for console and files -->
<!-- ::=is used to distinguish key and value while ||| is used as token separator -->
	<property name="CONSOLE_LOG_PATTERN"
		value="${CONSOLE_LOG_PATTERN:-%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) [%X{systemId},%X{appId},%X{requestId}] %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}" />
	<property name="FILE_LOG_PATTERN"
		value="%d{yyyy-MM-dd HH:mm:ss.SSS} ${LOG_LEVEL_PATTERN:-%5p} [%X{systemId},%X{appId},%X{requestId}] ${PID:- } --- [%t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}" />
	<property name="KAFKA_LOG_PATTERN"
		value="logtime::=%d{yyyy-MM-dd HH:mm:ss.SSS}|||appCode::=${appName}|||server::=${serverName:-${HOSTNAME}}|||instanceIdentifier::=${instance.identifier:-${appPort}}|||level::=%p|||systemId::=%X{systemId}|||appId::=%X{appId:-0}|||transactionId::=%X{requestId}|||pid::=${PID:-}|||thread::=%t|||className::=%logger|||message::=%m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}" />

---

DO’s: (How should we do proper logging)

1. DO Log the Exception Stacktrace

This is really important. Far too often you see code like this:

try { ... } catch (Exception e) {
    log.error("Something went wrong: " + e.getStackTrace());
}

2. DO Log Uncaught Exceptions

If you’re going to follow the advice above then obviously it’s vital that exception does get logged at some point, so make sure your application logs uncaught exceptions when it handles them. The default behavior of a standalone Java app is to call exception.printStackTrace(); you can override this as follows:

Thread.setDefaultUncaughtExceptionHandler(new Thread.UncaughtExceptionHandler() {
    @Override
    public void uncaughtException(Thread thread, Throwable e) {
        Logger log = LoggerFactory.getLogger(thread.getClass());
        log.error("Exception in thread [" + thread.getName() + "]", e);
    }
});

3. DO Use Parameterized Logging

Traditionally debug logging statements involving expensive string concatenation are wrapped in a check to save the expense of generating the message when the log is disabled:

if (log.isDebugEnabled()) {
    log.debug("created user[" + user + "] with role [" + role + "]");
}

With SLF4J you don’t need to use this rather noisy format and can get the same performance characteristics using parameterized logging:

log.debug("created user[{}] with role [{}]", user, role);

4. DO Use Aspect-Oriented Programming for Trace Logging

If you’re writing code like this:

public String doSomeWork(String param1, Integer param2) {
    log.trace("> doSomeWork[param1={}, param2={}]", param1, param2);
    String result = /* work done here */;
    log.trace("< doSomeWork[{}]", result);
    return result;
}

in every method then it’s time to find out about Aspect Oriented Programming. You can use something like AspectJ to add the trace statements to all methods at compile time, resulting in bytecode that contains the trace calls, or you can use instrumentation to add them to the loaded class at runtime.

5. DO Track A Single Operation Across Multiple Systems and Logs

In distributed systems with multiple, independent micro-services works together to process incoming requests, tracking a single request across all of these systems can be difficult.

A single request will very likely hit multiple of these services, and if a problem does occur, we’ll need to corroborate all of the individual logs of these systems to get the full picture of what happened.
Like currently we have TRANSACTION ID across the microservices, it travels along with each request from csm to all the further services.

---

DONT’s: (What mistakes to avoid while logging)

1. DON’T Log Sensitive Information

• Don’t log any Plain User input – not always possible, since the user data can be critical for getting to the root cause of some problems
• Use validation before logging – this solution can impact performance, as well as forego logging important information
• Log to a database – more secure but costly regarding performance, and can introduce another vulnerability (SQL injection)
• Use a tool like the Enterprise Security API from OWASP

2. DON’T do Excessive Logging

Too many log messages can also lead to difficulty in reading a log file and identifying the relevant information when a problem does occur.

One way to reduce the number of log lines of code is by logging important information across cross-cutting concerns in the system.

For example, if you want to log the start and end of particular methods, you can add an Aspect that will do this for every method that has a specified custom annotation.

3. DON’T choose Cryptic Log Messages

When parsing log files, encountering a line that doesn’t provide sufficient information can be frustrating. A common pitfall is the lack of specificity or context in log messages.
To illustrate the problem, let’s have a look at a log message lacking specificity:

Operation failed.

Instead, you can add more specific and identifiable information:

File upload picture.jpg failed.

Always keep in mind that your logs will most certainly be read by a different developer or system administrator, and they need to understand what has happened in the application.

4. DON’T Use a Single Log File

The downside of only using one log file for the application is, that this will, over time, become quite large and difficult to work with.

A good practice for quickly finding relevant information is to create a new log file each day, with the date as part of the file name.

<appender name="errorAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
		<encoder>
			<pattern>${FILE_LOG_PATTERN}</pattern>
		</encoder>
		<File>${ERROR_LOG_FILE}</File>
		<rollingPolicy
			class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
			<!-- daily rollover -->
			<FileNamePattern>${ERROR_LOG_FILE}.%i</FileNamePattern>
			<!-- keep 7 files of 100 mb each -->
			<minIndex>1</minIndex>
			<maxIndex>6</maxIndex>
		</rollingPolicy>
		<triggeringPolicy
			class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
			<maxFileSize>100MB</maxFileSize>
		</triggeringPolicy>
		<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
			<level>WARN</level>
		</filter>
	</appender>

5. DON’T Choose Incorrect Log Levels

Choosing an inadequate log level will lead to either missing significant events or being flooded with a lot of less important data. Choosing the right log level for the different logs in your system is one of the core things you need to get right to have a good experience understanding your logs.