Логирование в Java: что это такое и зачем оно нужно

О логировании

Мы создаем проекты, пишем код, потом запускаем наши проекты на продакшн. До этого мы запускаем их локально и смотрим как всё работает, итеративно внося правки и улучшая функционал. И это всё выглядит как типичный процесс разработки. Но как быть, если мы сталкиваемся с проблемами в коде, когда у нас что-то не работает или что-то неожиданно сломалось. Логирование приходит на помощь и помогает понять что происходит в коде во время выполнения.

Типичный пример приложения - интернет-магазин

Типичный флоу покупки

Представьте ситуацию, что у вас есть онлайн-магазин и вы продаете какой-то продукт. Процесс покупки состоит из нескольких логических шагов, где мы хотим:

1. Проверить существование продукта - что такой продукт действительно есть в нашей базе данных;
2. Убедиться, что это продукт доступен - есть на складе в нужном количестве;
3. Проверить, что у покупателя достаточно денег для покупки - что они есть на его счету в достаточном количестве;
4. Списать деньги со счета покупателя - чаще всего для этого используется сторонний шлюз и там могут возникать ошибки;
5. Зарезервировать продукт на складе - чтобы его не продали кому-то еще.

Вы ведете локальную разработку и пишете функционал, потом запускаете код локально и проверяете в браузере как всё работает.

Как быть, если что-то не работает

Мы написали какой-то функционал, запускаем - и код не работает как ожидалось. Что делать? У нас есть такие опции:

• Пройтись еще раз по коду в попытке понять в чем может быть дело. Может быть непросто, в особенности, если логика сложная;
• Вы можете запустить ваше приложение в режиме отладки, поставить точки останова (breakpoints) в коде и попытаться отладить, заглядывая каждый раз в статус приложения в тот или иной момент его выполнения. Обычно, это очень здорово помогает, ошибка находится и проблема решается;
• Вы можете добавить логи в "ключевые" места в коде, чтобы каждый раз во время запуска была возможность отслеживать поведение программы и даже ее состояние.

На самом деле, самым эффективным способом здесь будет комбинирование всех методов вместе, так как они просто дополняют друг друга.

А как быть, если мы в продакшн?

Как бы хорошо мы не отлаживали наши приложения во время разработки, мы не застрахованы от багов в продакшн. Логи могут быть очень полезными в продакшн. По логам вы сможете увидеть как выполняется ваш код и его состояние в тот или иной момент выполнения. Если логи были добавлены в код осмысленно и правильно, это может существенно ускорить поиск бага без подключения более сложных инструментов для отладки. О том как это сделать правильно мы поговорим дальше, а сейчас я хотел бы поговорить о том, как логирование работает в деталях и подробностях и как его настроить на примере Spring Boot проекта.

Практика! Смотрим на логи в сервисе заказа

Давайте посмотрим как выглядят логи в коде и какой вывод мы получаем в консоли. Ниже привожу пример сервиса, обрабатывающего покупку продукта в онлайн-магазине. Это весьма упрощенная версия, но довольно наглядная, чтобы понять идею логирования и осознать пользу, которую они несут.

package com.example.shop.service;

import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@Service
@RequiredArgsConstructor
public class OrderService {

  private final ProductService productService;
  private final PaymentService paymentService;
  private final InventoryService inventoryService;

  public void purchase(Long userId, Long productId, int quantity) {

    log.info("Purchase started: userId={}, productId={}, quantity={}",
        userId, productId, quantity);

    log.debug("Loading product with id={}", productId);
    Product product = productService.findById(productId)
        .orElseThrow(() -> {
          log.error("Product not found: productId={}", productId);
          return new ProductNotFoundException(productId);
        });

    log.debug("Product loaded: id={}, price={}", product.getId(), product.getPrice());

    int availableStock = inventoryService.getAvailableStock(productId);

    if (availableStock < quantity) {
      log.error("Not enough items in stock: productId={}, requested={}",
          productId, quantity);
      throw new IllegalStateException("Not enough items in stock");
    }

    if (availableStock - quantity <= 3) {
      log.warn("Low stock level after purchase: productId={}, remaining={}",
          productId, availableStock - quantity);
    }

    double totalPrice = product.getPrice() * quantity;
    log.debug("Total price calculated: {}", totalPrice);

    try {
      paymentService.charge(userId, totalPrice);
      log.info("Payment successful: userId={}, amount={}", userId, totalPrice);
    } catch (PaymentException ex) {
      log.error("Payment failed: userId={}, amount={}, reason={}",
          userId, totalPrice, ex.getMessage(), ex);
      throw ex;
    }

    inventoryService.reserve(productId, quantity);
    log.info("Product reserved: productId={}, quantity={}", productId, quantity);

    log.info("Purchase completed successfully: userId={}, productId={}",
        userId, productId);
  }
}

Когда все хорошо, мы видим такой лог

Если логика выполняется без ошибок, мы увидим такой лог:

INFO  Purchase started: userId=42, productId=10, quantity=2
INFO  Payment successful: userId=42, amount=399.98
INFO  Product reserved: productId=10, quantity=2
INFO  Purchase completed successfully: userId=42, productId=10

Такой вывод мы получаем, когда отладка выключена.

И больше логов, когда мы в режиме отладки

Когда мы включаем отладку, а она нам будет нужна, если нам не хватило стандартного вывода для понимания проблемы, мы видим такой лог:

INFO  Purchase started: userId=42, productId=10, quantity=2
DEBUG Loading product with id=10
DEBUG Product loaded: id=10, price=199.99
DEBUG Total price calculated: 399.98
INFO  Payment successful: userId=42, amount=399.98
INFO  Product reserved: productId=10, quantity=2
INFO  Purchase completed successfully: userId=42, productId=10

А если возникла ошибка в коде...

Представим, что по какой-то причине мы выводим на сайте продукт, которого нет в нашей базе данных. Это может быть связано например с тем, что какой-то продукт закешировался на странице, но был уже удален из базы (мы решили, что не хотим его больше продавать). В этом случае мы получим такой лог:

INFO  Purchase started: userId=42, productId=10, quantity=2
DEBUG Loading product with id=10
ERROR Product not found: productId=10

И приложение "упадет" с Exception. То есть дальнейшее выполнение флоу покупки прервется и мы больше не получим никаких логов. Покупатель не сможет купить товар в магазине. Мы же получим лог уровня ERROR и сможем по нему понять в чем было дело. Этот лог подскажет разработчику где искать проблему. Скорее всего кеширование в браузере работает неправильно и нужно после удаления товара из базы очищать кеш, чтобы не было фантомных продуктов на сайте.

В следующей статье мы поговорим про уровни логирования и почему это важно.