Capítulo 3: Logging con SLF4J

Introducción

System.out.println() está bien para depurar, pero en producción es inutilizable. SLF4J junto con Logback le proporciona un sistema de logging profesional.

---

🎯 Objetivos del Capítulo

Al final de este capítulo, usted sabrá:

1. ✅ Utilizar SLF4J en sus clases
2. ✅ Comprender los niveles de log
3. ✅ Escribir logs efectivos
4. ✅ Utilizar el MDC para la trazabilidad
5. ✅ Evitar errores comunes

---

1. SLF4J: La Fachada de Logging

Arquitectura

Su código
    ↓
SLF4J (API/Fachada)
    ↓
Logback (Implementación)
    ↓
Consola / Archivo / Cloud

Ventaja: Cambiar de implementación sin modificar el código.

Spring Boot lo incluye por defecto

<!-- Ya incluido en spring-boot-starter -->
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter</artifactId>
</dependency>
<!-- Contiene: spring-boot-starter-logging (SLF4J + Logback) -->

---

2. Crear un Logger

Método Clásico

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@Service
public class UserService {

    private static final Logger log = LoggerFactory.getLogger(UserService.class);

    public User findById(Long id) {
        log.info("Finding user with ID: {}", id);
        return userRepository.findById(id).orElse(null);
    }
}

Con Lombok @Slf4j (Recomendado)

import lombok.extern.slf4j.Slf4j;

@Slf4j  // ← Genera automáticamente el logger
@Service
public class UserService {

    public User findById(Long id) {
        log.info("Finding user with ID: {}", id);
        return userRepository.findById(id).orElse(null);
    }
}

---

3. Niveles de Log

Jerarquía (de menos a más crítico)

TRACE → DEBUG → INFO → WARN → ERROR

Nivel	Uso	Ejemplo
TRACE	Detalles muy finos	"Entering method X with params..."
DEBUG	Información de depuración	"Calculated value: 42"
INFO	Eventos normales	"User logged in", "Order created"
WARN	Posibles problemas	"Cache miss", "Retrying connection"
ERROR	Errores	"Failed to save", "Connection refused"

Uso

@Slf4j
@Service
public class OrderService {

    public Order processOrder(Order order) {
        log.trace("Entering processOrder with order: {}", order);
        
        log.debug("Validating order items: {} items", order.getItems().size());
        
        log.info("Processing order {} for user {}", order.getId(), order.getUserId());
        
        if (order.getTotal() > 10000) {
            log.warn("Large order detected: {} - Total: {}", order.getId(), order.getTotal());
        }
        
        try {
            return saveOrder(order);
        } catch (Exception e) {
            log.error("Failed to process order {}: {}", order.getId(), e.getMessage(), e);
            throw e;
        }
    }
}

---

4. Buenas Prácticas de Logging

✅ Utilizar Placeholders

// ✅ BIEN: Placeholders (rendimiento óptimo)
log.debug("Processing user {} with email {}", userId, email);

// ❌ MAL: Concatenación (siempre evaluada)
log.debug("Processing user " + userId + " with email " + email);

✅ Loggear Excepciones Correctamente

try {
    riskyOperation();
} catch (Exception e) {
    // ✅ BIEN: Excepción como último parámetro (muestra el stack trace)
    log.error("Operation failed for user {}: {}", userId, e.getMessage(), e);
    
    // ❌ MAL: Sin stack trace
    log.error("Operation failed: " + e.getMessage());
    
    // ❌ MAL: e.printStackTrace() en vez de logger
    e.printStackTrace();
}

✅ Logs Útiles y Contextuales

// ✅ BIEN: Contexto suficiente
log.info("Order {} created for user {} - Total: {} - Items: {}", 
    order.getId(), order.getUserId(), order.getTotal(), order.getItems().size());

// ❌ MAL: Sin contexto
log.info("Order created");

// ❌ MAL: Demasiado verboso
log.info("Created order object with ID " + order.getId() + " and this order was created by user with ID " + order.getUserId() + "...");

✅ Evitar el Log Spam

// ❌ MAL: Log en un bucle
for (Item item : items) {
    log.debug("Processing item: {}", item);  // ¡1000 logs si hay 1000 items!
}

// ✅ BIEN: Log resumido
log.debug("Processing {} items", items.size());
for (Item item : items) {
    // procesamiento...
}
log.debug("Finished processing items");

---

5. Verificación del Nivel

Para Operaciones Costosas

// Si el cálculo es costoso, verifique el nivel primero
if (log.isDebugEnabled()) {
    String expensiveDetails = calculateExpensiveDetails(order);
    log.debug("Order details: {}", expensiveDetails);
}

// Alternativa con Java 8 Supplier (Logback 1.3+)
log.atDebug()
    .addArgument(() -> calculateExpensiveDetails(order))
    .log("Order details: {}");

---

6. MDC (Mapped Diagnostic Context)

¿Qué es el MDC?

El MDC permite añadir contexto a todos los logs de una petición (userId, requestId, etc.).

Uso Básico

import org.slf4j.MDC;

@Component
public class LoggingFilter implements Filter {

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) 
            throws IOException, ServletException {
        
        try {
            // Añadir el contexto
            MDC.put("requestId", UUID.randomUUID().toString());
            MDC.put("userId", getCurrentUserId());
            
            chain.doFilter(request, response);
        } finally {
            // IMPORTANTE: ¡Siempre limpiar!
            MDC.clear();
        }
    }
}

Resultado en los Logs

2024-01-15 10:30:00 [requestId=abc-123] [userId=42] INFO  OrderService - Processing order
2024-01-15 10:30:01 [requestId=abc-123] [userId=42] INFO  PaymentService - Payment processed
2024-01-15 10:30:01 [requestId=abc-123] [userId=42] INFO  EmailService - Confirmation sent

Filtro Completo con MDC

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class MdcLoggingFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest request, 
                                     HttpServletResponse response, 
                                     FilterChain filterChain) 
            throws ServletException, IOException {
        
        try {
            // Request ID
            String requestId = request.getHeader("X-Request-ID");
            if (requestId == null) {
                requestId = UUID.randomUUID().toString().substring(0, 8);
            }
            MDC.put("requestId", requestId);
            
            // User ID (si está autenticado)
            Authentication auth = SecurityContextHolder.getContext().getAuthentication();
            if (auth != null && auth.isAuthenticated()) {
                MDC.put("userId", auth.getName());
            }
            
            // Path
            MDC.put("path", request.getRequestURI());
            
            // Añadir el requestId en la respuesta
            response.setHeader("X-Request-ID", requestId);
            
            filterChain.doFilter(request, response);
            
        } finally {
            MDC.clear();
        }
    }
}

---

7. Logging en las Diferentes Capas

Controller

@Slf4j
@RestController
@RequestMapping("/api/orders")
public class OrderController {

    @PostMapping
    public ResponseEntity<Order> create(@RequestBody OrderRequest request) {
        log.info("Received order creation request: {} items", request.getItems().size());
        
        Order order = orderService.create(request);
        
        log.info("Order {} created successfully", order.getId());
        return ResponseEntity.status(HttpStatus.CREATED).body(order);
    }
}

Service

@Slf4j
@Service
public class OrderService {

    public Order create(OrderRequest request) {
        log.debug("Creating order for user {}", request.getUserId());
        
        // Validación
        validateItems(request.getItems());
        
        // Cálculo
        BigDecimal total = calculateTotal(request.getItems());
        log.debug("Calculated total: {}", total);
        
        // Guardado
        Order order = orderRepository.save(toOrder(request, total));
        
        log.info("Order {} saved with total {}", order.getId(), total);
        return order;
    }
}

Repository (opcional)

// Los logs de JPA/Hibernate suelen ser suficientes
// Pero para consultas personalizadas:

@Slf4j
@Repository
public class CustomOrderRepository {

    public List<Order> findComplexQuery(Criteria criteria) {
        log.debug("Executing complex query with criteria: {}", criteria);
        
        List<Order> results = executeQuery(criteria);
        
        log.debug("Query returned {} results", results.size());
        return results;
    }
}

---

8. Configuración Rápida

application.properties

# Nivel global
logging.level.root=INFO

# Nivel por paquete
logging.level.com.myapp=DEBUG
logging.level.com.myapp.repository=TRACE

# Mostrar las consultas SQL
logging.level.org.hibernate.SQL=DEBUG
logging.level.org.hibernate.type.descriptor.sql.BasicBinder=TRACE

# Desactivar logs ruidosos
logging.level.org.apache.catalina=WARN
logging.level.org.springframework.web=INFO

Niveles Recomendados

Entorno	Root	Aplicación	Hibernate
Dev	INFO	DEBUG	DEBUG
Test	WARN	INFO	WARN
Prod	WARN	INFO	WARN

---

9. Resumen

Crear un Logger

// Con Lombok (recomendado)
@Slf4j
public class MyClass {
    void method() {
        log.info("Message");
    }
}

// Sin Lombok
private static final Logger log = LoggerFactory.getLogger(MyClass.class);

Niveles

TRACE < DEBUG < INFO < WARN < ERROR

Buenas Prácticas

// Placeholders
log.info("User {} logged in", userId);

// Excepción con stack trace
log.error("Failed: {}", e.getMessage(), e);

// MDC para el contexto
MDC.put("requestId", "abc-123");

---

🎯 Próximo Paso

Ya sabe cómo hacer logging. Ahora, configuremos Logback para controlar dónde y cómo se escriben los logs.

➡️ Capítulo 4: Configuración Logback

---

⬅️ Volver al Módulo 10