Introduction
Effective log message formatting is crucial for debugging, monitoring, and maintaining applications. Template-based logging provides structured, consistent, and performant log messages that are easily parsable by logging systems and humans alike.
Basic String Formatting Approaches
Traditional String Concatenation
public class BasicLogFormatting {
public void traditionalConcatenation(String user, int attempts, String status) {
// Inefficient - creates multiple string objects
logger.info("User: " + user + " made " + attempts + " attempts. Status: " + status);
}
public void stringFormat(String user, int attempts, String status) {
// Better - single string creation
logger.info(String.format("User: %s made %d attempts. Status: %s",
user, attempts, status));
}
public void messageFormat(String user, int attempts, String status) {
// More flexible formatting
String pattern = "User: {0} made {1} attempts. Status: {2}";
logger.info(MessageFormat.format(pattern, user, attempts, status));
}
}
Template-Based Logging Frameworks
SLF4J with Parameterized Messages
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class SLF4JTemplateLogging {
private static final Logger logger = LoggerFactory.getLogger(SLF4JTemplateLogging.class);
public void basicParameterizedLogging(String userId, String action, int duration) {
// SLF4J parameterized logging - efficient and clean
logger.info("User {} performed action {} in {} ms", userId, action, duration);
// With exception logging
try {
processUserAction(userId, action);
} catch (Exception e) {
logger.error("Failed to process action {} for user {}", action, userId, e);
}
}
public void complexParameterizedLogging(User user, Order order, double amount) {
logger.debug(
"Processing order {} for user {} with amount ${:.2f}",
order.getId(),
user.getUsername(),
amount
);
}
// Conditional logging with templates
public void conditionalLogging(String transactionId, boolean isHighValue) {
if (logger.isDebugEnabled()) {
logger.debug("Processing transaction {} - high value: {}",
transactionId, isHighValue);
}
// More efficient - parameter evaluation is lazy
logger.debug("Processing transaction {} - high value: {}",
transactionId, isHighValue);
}
private void processUserAction(String userId, String action) {
// Simulate business logic
}
}
Logback Configuration with Templates
<!-- logback.xml -->
<configuration>
<!-- Custom pattern with structured data -->
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - [user:%X{userId}] [session:%X{sessionId}] %msg%n</pattern>
</encoder>
</appender>
<!-- JSON layout for structured logging -->
<appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="net.logstash.logback.encoder.LogstashEncoder">
<template>
{
"timestamp": "%d{yyyy-MM-dd HH:mm:ss.SSS}",
"level": "%level",
"thread": "%thread",
"logger": "%logger{40}",
"message": "#asJson{%message}",
"user_id": "%mdc{userId}",
"session_id": "%mdc{sessionId}",
"exception": "%exception"
}
</template>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="CONSOLE" />
<appender-ref ref="JSON" />
</root>
</configuration>
Advanced Template Systems
Custom Template Engine with StringTemplate
import org.stringtemplate.v4.ST;
public class StringTemplateLogging {
private static final Map<String, String> LOG_TEMPLATES = Map.of(
"USER_LOGIN", "User <username> logged in from IP <ip> at <timestamp>",
"ORDER_CREATED", "Order <orderId> created by user <userId> with <itemCount> items totaling $<amount>",
"API_CALL", "API <method> <endpoint> called by <client> - Status: <status>, Duration: <duration>ms",
"ERROR", "Error <errorCode> in <component>: <message> - Context: <context>"
);
public void logWithTemplate(String templateKey, Map<String, Object> parameters) {
String template = LOG_TEMPLATES.get(templateKey);
if (template != null) {
ST st = new ST(template);
parameters.forEach(st::add);
logger.info(st.render());
}
}
public void demonstrateTemplateUsage() {
// User login event
logWithTemplate("USER_LOGIN", Map.of(
"username", "john_doe",
"ip", "192.168.1.100",
"timestamp", Instant.now().toString()
));
// Order creation event
logWithTemplate("ORDER_CREATED", Map.of(
"orderId", "ORD-12345",
"userId", "user-67890",
"itemCount", 5,
"amount", "99.99"
));
// API call event
logWithTemplate("API_CALL", Map.of(
"method", "POST",
"endpoint", "/api/orders",
"client", "web-app",
"status", 201,
"duration", 150
));
}
}
Mustache Template Engine for Logging
import com.github.mustachejava.Mustache;
import com.github.mustachejava.MustacheFactory;
public class MustacheTemplateLogging {
private final MustacheFactory mustacheFactory;
private final Map<String, Mustache> templateCache;
public MustacheTemplateLogging() {
this.mustacheFactory = new DefaultMustacheFactory();
this.templateCache = new ConcurrentHashMap<>();
}
private Mustache getTemplate(String templateName) {
return templateCache.computeIfAbsent(templateName,
key -> mustacheFactory.compile("templates/" + key + ".mustache"));
}
public void logWithMustache(String templateName, Object context) {
Mustache template = getTemplate(templateName);
StringWriter writer = new StringWriter();
template.execute(writer, context);
logger.info(writer.toString());
}
// Template context classes
public static class LoginContext {
public String username;
public String ip;
public String timestamp;
public boolean success;
public LoginContext(String username, String ip, String timestamp, boolean success) {
this.username = username;
this.ip = ip;
this.timestamp = timestamp;
this.success = success;
}
}
public static class OrderContext {
public String orderId;
public String userId;
public int itemCount;
public double amount;
public List<String> items;
public OrderContext(String orderId, String userId, int itemCount, double amount, List<String> items) {
this.orderId = orderId;
this.userId = userId;
this.itemCount = itemCount;
this.amount = amount;
this.items = items;
}
}
public void demonstrateMustacheLogging() {
// Login event
LoginContext login = new LoginContext("alice", "10.0.1.50",
Instant.now().toString(), true);
logWithMustache("login", login);
// Order event
OrderContext order = new OrderContext("ORD-67890", "user-12345",
3, 149.99, List.of("Laptop", "Mouse", "Keyboard"));
logWithMustache("order", order);
}
}
Structured Logging with JSON
JSON Template Logging
import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.core.JsonProcessingException;
public class JSONTemplateLogging {
private static final ObjectMapper mapper = new ObjectMapper();
private static final Logger logger = LoggerFactory.getLogger(JSONTemplateLogging.class);
// JSON log event templates
public static class LogEvent {
public final String timestamp;
public final String level;
public final String logger;
public final String message;
public final Map<String, Object> context;
public LogEvent(String level, String logger, String message, Map<String, Object> context) {
this.timestamp = Instant.now().toString();
this.level = level;
this.logger = logger;
this.message = message;
this.context = context;
}
}
public void logJSON(String level, String message, Map<String, Object> context) {
LogEvent event = new LogEvent(level, this.getClass().getSimpleName(), message, context);
try {
String json = mapper.writeValueAsString(event);
switch (level) {
case "INFO" -> logger.info(json);
case "WARN" -> logger.warn(json);
case "ERROR" -> logger.error(json);
case "DEBUG" -> logger.debug(json);
default -> logger.info(json);
}
} catch (JsonProcessingException e) {
logger.error("Failed to serialize log event to JSON", e);
}
}
public void demonstrateJSONLogging() {
// User activity
logJSON("INFO", "User login successful", Map.of(
"user_id", "user-123",
"ip_address", "192.168.1.100",
"user_agent", "Mozilla/5.0...",
"session_duration_sec", 3600
));
// Business transaction
logJSON("INFO", "Order processed", Map.of(
"order_id", "ORD-98765",
"customer_id", "CUST-54321",
"total_amount", 199.99,
"currency", "USD",
"payment_method", "credit_card",
"items_count", 2
));
// Error with context
logJSON("ERROR", "Payment processing failed", Map.of(
"transaction_id", "TXN-11111",
"error_code", "INSUFFICIENT_FUNDS",
"amount_attempted", 150.00,
"available_balance", 100.00,
"retry_count", 3
));
}
// Fluent API for JSON logging
public JSONLogger withContext(String key, Object value) {
return new JSONLogger().withContext(key, value);
}
public static class JSONLogger {
private final Map<String, Object> context = new HashMap<>();
public JSONLogger withContext(String key, Object value) {
context.put(key, value);
return this;
}
public void info(String message) {
logJSON("INFO", message, context);
}
public void error(String message) {
logJSON("ERROR", message, context);
}
public void warn(String message) {
logJSON("WARN", message, context);
}
}
public void demonstrateFluentJSONLogging() {
withContext("user_id", "user-999")
.withContext("action", "profile_update")
.withContext("changes_count", 3)
.info("User profile updated successfully");
withContext("api_endpoint", "/api/v1/payments")
.withContext("response_time_ms", 245)
.withContext("status_code", 500)
.error("Internal server error in payment API");
}
}
Performance-Optimized Template Logging
Cached Message Templates
public class CachedTemplateLogging {
private static final Logger logger = LoggerFactory.getLogger(CachedTemplateLogging.class);
// Template cache for performance
private static final Map<String, MessageFormat> templateCache = new ConcurrentHashMap<>();
private MessageFormat getCachedTemplate(String pattern) {
return templateCache.computeIfAbsent(pattern, MessageFormat::new);
}
public void logWithCachedTemplate(String pattern, Object... args) {
if (logger.isInfoEnabled()) {
MessageFormat formatter = getCachedTemplate(pattern);
String message = formatter.format(args);
logger.info(message);
}
}
// Pre-compiled templates for common log messages
private static final MessageFormat USER_LOGIN_TEMPLATE =
new MessageFormat("User {0} logged in from {1} at {2}");
private static final MessageFormat ORDER_TEMPLATE =
new MessageFormat("Order {0} created for {1} with {2} items");
private static final MessageFormat ERROR_TEMPLATE =
new MessageFormat("Error in {0}: {1} (Code: {2})");
public void logUserLogin(String username, String ip, Instant timestamp) {
if (logger.isInfoEnabled()) {
String message = USER_LOGIN_TEMPLATE.format(new Object[]{username, ip, timestamp});
logger.info(message);
}
}
public void logOrderCreation(String orderId, String customer, int itemCount) {
if (logger.isInfoEnabled()) {
String message = ORDER_TEMPLATE.format(new Object[]{orderId, customer, itemCount});
logger.info(message);
}
}
public void logError(String component, String message, String errorCode) {
if (logger.isErrorEnabled()) {
String formattedMessage = ERROR_TEMPLATE.format(new Object[]{component, message, errorCode});
logger.error(formattedMessage);
}
}
}
Lazy Evaluation for Expensive Operations
public class LazyTemplateLogging {
private static final Logger logger = LoggerFactory.getLogger(LazyTemplateLogging.class);
@FunctionalInterface
public interface LazyMessageSupplier {
String get();
}
// Lazy message evaluation for expensive operations
public void logDebug(LazyMessageSupplier messageSupplier) {
if (logger.isDebugEnabled()) {
logger.debug(messageSupplier.get());
}
}
public void logInfo(LazyMessageSupplier messageSupplier) {
if (logger.isInfoEnabled()) {
logger.info(messageSupplier.get());
}
}
public void demonstrateLazyLogging() {
String userId = "user-123";
String action = "complex_operation";
// Expensive operation only executed if debug is enabled
logDebug(() -> {
String expensiveData = generateExpensiveDebugInfo(userId, action);
return String.format("User %s performed %s: %s", userId, action, expensiveData);
});
// Complex context building only if info is enabled
logInfo(() -> {
Map<String, Object> context = buildComplexContext(userId);
return String.format("Processing user %s with context: %s", userId, context);
});
}
private String generateExpensiveDebugInfo(String userId, String action) {
// Simulate expensive operation
try {
Thread.sleep(100);
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
}
return "Expensive debug data for " + userId;
}
private Map<String, Object> buildComplexContext(String userId) {
// Simulate complex context building
Map<String, Object> context = new HashMap<>();
context.put("user_profile", loadUserProfile(userId));
context.put("permissions", loadUserPermissions(userId));
context.put("preferences", loadUserPreferences(userId));
return context;
}
// Mock methods
private Object loadUserProfile(String userId) { return "Profile"; }
private Object loadUserPermissions(String userId) { return "Permissions"; }
private Object loadUserPreferences(String userId) { return "Preferences"; }
}
Domain-Specific Logging Templates
E-Commerce Logging Templates
public class ECommerceLoggingTemplates {
private static final Logger logger = LoggerFactory.getLogger(ECommerceLoggingTemplates.class);
public static class ECommerceLogger {
private final String component;
public ECommerceLogger(String component) {
this.component = component;
}
public void logProductView(String productId, String userId, String sessionId) {
logger.info("[PRODUCT_VIEW] component={} product_id={} user_id={} session_id={}",
component, productId, userId, sessionId);
}
public void logAddToCart(String productId, String userId, int quantity, double price) {
logger.info("[ADD_TO_CART] component={} product_id={} user_id={} quantity={} price={}",
component, productId, userId, quantity, price);
}
public void logCheckoutStart(String orderId, String userId, int itemCount, double total) {
logger.info("[CHECKOUT_START] component={} order_id={} user_id={} items={} total={}",
component, orderId, userId, itemCount, total);
}
public void logPaymentProcessed(String orderId, String paymentId, String status, double amount) {
logger.info("[PAYMENT_PROCESSED] component={} order_id={} payment_id={} status={} amount={}",
component, orderId, paymentId, status, amount);
}
public void logInventoryUpdate(String productId, int oldStock, int newStock, String reason) {
logger.info("[INVENTORY_UPDATE] component={} product_id={} old_stock={} new_stock={} reason={}",
component, productId, oldStock, newStock, reason);
}
}
public void demonstrateECommerceLogging() {
ECommerceLogger catalogLogger = new ECommerceLogger("catalog");
ECommerceLogger cartLogger = new ECommerceLogger("shopping_cart");
ECommerceLogger paymentLogger = new ECommerceLogger("payment");
// Product browsing
catalogLogger.logProductView("PROD-123", "USER-456", "SESS-789");
// Shopping cart actions
cartLogger.logAddToCart("PROD-123", "USER-456", 2, 29.99);
// Checkout process
cartLogger.logCheckoutStart("ORDER-111", "USER-456", 3, 89.97);
paymentLogger.logPaymentProcessed("ORDER-111", "PAY-222", "SUCCESS", 89.97);
// Inventory management
catalogLogger.logInventoryUpdate("PROD-123", 50, 48, "SALE");
}
}
API Request/Response Logging Templates
public class APILoggingTemplates {
private static final Logger logger = LoggerFactory.getLogger(APILoggingTemplates.class);
public static class APIRequestLog {
public String method;
public String path;
public String clientIp;
public String userAgent;
public Map<String, String> headers;
public String queryParams;
public String requestBody;
public long timestamp;
public void log() {
logger.info("[API_REQUEST] method={} path={} client_ip={} user_agent={} query_params={}",
method, path, clientIp, userAgent, queryParams);
if (logger.isDebugEnabled() && requestBody != null && !requestBody.isEmpty()) {
logger.debug("[API_REQUEST_BODY] body={}", requestBody);
}
}
}
public static class APIResponseLog {
public String method;
public String path;
public int statusCode;
public long durationMs;
public String responseBody;
public Map<String, String> headers;
public void log() {
String level = statusCode >= 400 ? "ERROR" : "INFO";
if ("ERROR".equals(level)) {
logger.error("[API_RESPONSE] method={} path={} status={} duration_ms={}",
method, path, statusCode, durationMs);
} else {
logger.info("[API_RESPONSE] method={} path={} status={} duration_ms={}",
method, path, statusCode, durationMs);
}
}
}
public void demonstrateAPILogging() {
// Request logging
APIRequestLog requestLog = new APIRequestLog();
requestLog.method = "POST";
requestLog.path = "/api/v1/orders";
requestLog.clientIp = "192.168.1.100";
requestLog.userAgent = "Mozilla/5.0...";
requestLog.queryParams = "expand=items";
requestLog.requestBody = "{\"items\": [{\"id\": \"PROD-1\", \"qty\": 2}]}";
requestLog.log();
// Response logging
APIResponseLog responseLog = new APIResponseLog();
responseLog.method = "POST";
responseLog.path = "/api/v1/orders";
responseLog.statusCode = 201;
responseLog.durationMs = 150;
responseLog.log();
}
// HTTP filter for automatic API logging
@Component
public class APILoggingFilter implements WebFilter {
@Override
public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
long startTime = System.currentTimeMillis();
ServerHttpRequest request = exchange.getRequest();
// Log request
APIRequestLog requestLog = new APIRequestLog();
requestLog.method = request.getMethodValue();
requestLog.path = request.getPath().value();
requestLog.clientIp = getClientIp(request);
requestLog.timestamp = System.currentTimeMillis();
requestLog.log();
return chain.filter(exchange).doOnSuccessOrError((result, error) -> {
long duration = System.currentTimeMillis() - startTime;
ServerHttpResponse response = exchange.getResponse();
// Log response
APIResponseLog responseLog = new APIResponseLog();
responseLog.method = request.getMethodValue();
responseLog.path = request.getPath().value();
responseLog.statusCode = response.getStatusCode() != null ?
response.getStatusCode().value() : 500;
responseLog.durationMs = duration;
responseLog.log();
});
}
private String getClientIp(ServerHttpRequest request) {
String xForwardedFor = request.getHeaders().getFirst("X-Forwarded-For");
if (xForwardedFor != null && !xForwardedFor.isEmpty()) {
return xForwardedFor.split(",")[0].trim();
}
return request.getRemoteAddress() != null ?
request.getRemoteAddress().getAddress().getHostAddress() : "unknown";
}
}
}
Configuration and Best Practices
Logback Configuration with Custom Patterns
<!-- logback-spring.xml -->
<configuration>
<!-- Environment-specific templates -->
<springProfile name="dev">
<property name="LOG_PATTERN" value="%d{HH:mm:ss.SSS} [%thread] %highlight(%-5level) %cyan(%logger{36}) - %msg%n"/>
</springProfile>
<springProfile name="prod">
<property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - [traceId:%X{traceId}] [spanId:%X{spanId}] %msg%n"/>
</springProfile>
<!-- Structured logging for production -->
<springProfile name="prod & json">
<appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
<providers>
<timestamp/>
<logLevel/>
<loggerName/>
<message/>
<mdc/>
<stackTrace/>
</providers>
</encoder>
</appender>
</springProfile>
<root level="INFO">
<appender-ref ref="CONSOLE" />
</root>
</configuration>
Best Practices Class
public class LoggingBestPractices {
private static final Logger logger = LoggerFactory.getLogger(LoggingBestPractices.class);
// 1. Use parameterized logging
public void goodParameterizedLogging(String userId, String action, int count) {
logger.info("User {} performed action {} {} times", userId, action, count);
}
// 2. Avoid string concatenation in log messages
public void badLogging(String userId, String action) {
// Bad - creates unnecessary strings
logger.info("User " + userId + " performed " + action);
}
// 3. Use lazy evaluation for expensive operations
public void goodLazyLogging(Supplier<String> expensiveOperation) {
if (logger.isDebugEnabled()) {
logger.debug("Expensive data: {}", expensiveOperation.get());
}
}
// 4. Include context in log messages
public void logWithContext(String transactionId, String component, String operation) {
MDC.put("transactionId", transactionId);
try {
logger.info("Processing {} in {}", operation, component);
} finally {
MDC.clear();
}
}
// 5. Use consistent log formats
public void consistentFormatting(String eventType, String entityId, String action) {
logger.info("[{}] entity_id={} action={}", eventType, entityId, action);
}
// 6. Template for different log levels
public void logWithLevel(Level level, String template, Object... args) {
switch (level) {
case DEBUG -> logger.debug(template, args);
case INFO -> logger.info(template, args);
case WARN -> logger.warn(template, args);
case ERROR -> logger.error(template, args);
}
}
// 7. Structured logging for machine parsing
public void structuredLog(String event, Map<String, Object> fields) {
StringBuilder sb = new StringBuilder();
sb.append("event=").append(event);
fields.forEach((key, value) -> sb.append(" ").append(key).append("=").append(value));
logger.info(sb.toString());
}
public enum Level {
DEBUG, INFO, WARN, ERROR
}
}
Conclusion
Effective log message formatting with templates provides:
- Consistency - Uniform log format across the application
- Performance - Reduced string creation and better memory usage
- Maintainability - Easy to update log formats across the codebase
- Parsability - Structured logs that are easy to parse and analyze
- Context - Rich contextual information for debugging and monitoring
By implementing template-based logging strategies, developers can create more maintainable, performant, and useful logging systems that scale with application complexity and provide valuable insights during development and production operations.