우아한테크코스/학습 정리

[Logging] Slack 알림 메세지 Logger 구현하기

_Hiiro 2023. 8. 28. 01:16

들어가면서

 

기존에 하루스터디 팀 프로젝트를 진행하면서 스프링 콘솔에서 출력되던 스프링 자체 로깅 메세지와 HTTP 웹 요청 / 응답 메세지 값들을 로깅하고자 했습니다. 이를 수행하기 위해 LogBack에서 기본으로 제공하는 Appender 중 RollingFileAppender를 채택해서 사용했습니다. 기본적으로 서버에 파일로 로깅 데이터를 남긴 후 그라파나로 시각화하여 로그를 조회할 수 있는 시스템을 구축하는 것이 최종적인 목표였기 때문입니다.

그러던 중 서버에서 에러 로그가 발생하면 자동으로 백엔드 팀 슬랙에 알림이 오도록 기능을 추가하고 싶어졌습니다. 현재는 서버에서 에러가 발생했는지 여부를 확인하기 위해 팀원들이 직접 그라파나에 접속해서 확인해야 했는데 이를 매번 주기적으로 확인하기란 쉽지 않습니다. 그래서 백엔드 팀에서 직접 확인해봐야할 에러 로그가 발생했을 때 알림을 통해 이를 인지할 수 있도록 슬랙 알림 메세지 시스템을 구축하기로 결정했습니다.

 

 

 


해결 방안 도출 과정

 

우리가 사용하는 Logger들은 LoggingEvent를 Appender에게 전달합니다. Appender가 실질적인 로깅 작업을 수행하는 것이라고 봐도 과언이 아닙니다. 우리는 일반적으로 로깅을 한다고 하면 파일이나 콘솔에 출력하는 것만을 생각하기 쉬운데, 더 확장된 기능들을 위해 LogBack-core와 LogBack-classic은 아래와 같이 다양한 Appender들을 제공하고 있습니다.

- ConsoleAppender
- FileAppender
- RollingFileAppender
- OutputStreamAppender
- SMTPAppender
- DBAppender
- SocketAppender
- SyslogAppender

여러가지 Appender들이 제공됨을 확인할 수 있지만 슬랙과 같이 외부로 로깅 메세지를 전송해야 할 때 사용해야 하는 Appender는 딱히 제공되지 않는 것으로 보입니다. 이를 해결하기 위해 Logback 공식문서를 참고해봅니다.

 

LogBack 공식문서에서 제시하는 Appender 상속 구조

 

위와 같이 Appender의 상속 구조도를 보면 AppenderBase를 활용하면 뭔가 원하는 대로 Customizing할 수 있을 것 같습니다. LogBack 공식문서를 찾아보면 AppenderBase 추상클래스를 상속하도록 해서 CustomAppender를 구현할 수 있다고 합니다. 기본적으로 append(Object eventObject) 메서드를 구현하면 된다고 합니다. 공식문서의 예시를 참고해서 SlackAppender를 직접 구현해본다면 다음과 같은 형태가 될 것 같습니다.

public class SlackAppender extends AppenderBase<ILoggingEvent> {

    @Override
    protected void append(ILoggingEvent eventObject) {
        // ILoggingEvent 객체에 담겨있는 로깅 데이터를 메세지로 만들어서
        // Slack에 알림 메세지를 전송한다
    }
}



그런데 상속받은 AppenderBase 추상클래스 내부를 살펴보면 다음과 같은 doAppend() 메서드를 구현하고 있는 것을 확인할 수 있습니다.

public synchronized void doAppend(E eventObject) {

  // prevent re-entry.
  if (guard) {
    return;
  }

  try {
    guard = true;

    if (!this.started) {
      if (statusRepeatCount++ < ALLOWED_REPEATS) {
        addStatus(new WarnStatus(
            "Attempted to append to non started appender [" + name + "].",this));
      }
      return;
    }

    if (getFilterChainDecision(eventObject) == FilterReply.DENY) {
      return;
    }
    
    // ok, we now invoke the derived class's implementation of append
    this.append(eventObject);

  } finally {
    guard = false;
  }
}


AppenderBase 추상클래스 내부에는 위처럼 doAppend() 메서드를 구현하고 있습니다. 여기에서 주목할만한 부분은 synchronized, 즉 동기화를 사용해서 작업이 수행된다는 점입니다. 이에 대해 공식문서에서는 다음과 같이 설명합니다.

 

 

💡 This implementation of the doAppend() method is synchronized. It follows that logging to the same appender from different threads is safe. While a thread, say T, is executing the doAppend() method, subsequent calls by other threads are queued until T leaves the doAppend() method, ensuring T's exclusive access to the appender.

간단하게 정리하자면, 동기화를 하면서 작업이 수행되기 때문에 선행하는 스레드가 Appender를 통해 로깅 작업을 수행하는 동안 다른 스레드는 대기해야 하며 순서대로 작업이 수행된다는 것입니다.

현재 저희가 구현하려는 슬랙 알림 기능은 에러 로그가 발생했을 때 슬랙에 알림이 오기만 하면 됩니다. 만약 여러 스레드에서 에러 로깅이 동시에 발생한다고 하더라도 발생한 순서를 반드시 보장할 필요는 없습니다. 가능성이 희박하긴 하지만 이런 동기화 기능으로 인해 오히려 정상적인 에러 발생 알림 기능에 병목을 발생시킬 여지를 제공할 수도 있습니다. 

LogBack에서는 이렇게 동기화기능을 제공하는 AppenderBase가 적합하지 않을 경우 사용할 수 있는 UnsynchronizedAppenderBase 또한 제공합니다. 하지만 이 경우 비동기 처리 로직을 직접 구현해줘야 한다는 단점이 존재했습니다. 그래서 비동기 로직까지 구현되어 있어 편하게 사용할 수 있는 AsyncAppender를 사용해서 CustomSlackAppender를 구현하기로 결정했습니다.

 

 

 


구현 과정

 

<included>
  <appender name="SLACK_APPENDER" class="com.example.logprc.logging.SlackAppender">
  </appender>

  <shutdownHook class="ch.qos.logback.core.hook.DelayingShutdownHook"/> <!-- 애플리케이션 종료 시 비동기로 로깅을 처리하는 스레드를 전부 Shutdown될 수 있도록 합니다 -->
  <appender name="ASYNC_SLACK_APPENDER" class="ch.qos.logback.classic.AsyncAppender">
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>ERROR</level>
    </filter>
    <appender-ref ref="SLACK_APPENDER"/>
    <discardingThreshold>0</discardingThreshold>  <!-- LoggingEvent queue가 가득 차지 않은 상황에서 데이터가 누락되지 않도록 0으로 설정해줍니다 -->
    <neverBlock>true</neverBlock>  <!-- LoggingEvent queue가 가득 찼을 때 다른 로깅 스레드가 block 되지 않고 log를 누락시키며 application이 blocking되지 않도록 합니다 -->
  </appender>
</included>

 

 

먼저 slack-appender.xml 파일을 위와 같이 작성해줍니다. 옵션에 대한 자세한 설명은 주석으로 대체합니다. AsyncAppender의 세부 옵션에 대한 정보는 공식문서나 다음 레퍼런스를 참고해주시면 좋을 것 같습니다.

 

그리고 위쪽에 shutdownHook을 설정해준 것도 확인할 수 있습니다. 이는 비동기로 로깅을 수행하는 스레드들이 애플리케이션 생명주기가 종료될 때 함께 종료될 수 있도록 합니다. 이렇게 직접 종료해주는 hook을 걸어두지 않으면 유사 시 메모리 누수에 대한 직접적인 원인이 될 수 있기에 서버가 종료될 때 자동으로 함께 종료될 수 있도록 하는 설정입니다.

 

💡 POST SHUTDOWN CLEANUP

Depending on the mode of JVM shutdown, the worker thread processing the queued events can be interrupted causing events to be stranded in the queue. This generally occurs when the LoggerContext is not stopped cleanly or when the JVM terminates outside of the typical control flow. In order to avoid interrupting the worker thread under these conditions, a shutdown hook can be inserted to the JVM runtime that stops the LoggerContext properly after JVM shutdown has been initiated. A shutdown hook may also be the preferred method for cleanly shutting down Logback when other shutdown hooks attempt to log events.

자세한 내용이 궁금하신 분들을 위해 공식문서의 AsyncAppender의 일부를 인용하고 참고한 레퍼런스를 따로 남깁니다.

 

 

 

다음으로 logback-spring.xml 파일에 앞 단계에서 작성한 slack-appender.xml 파일을 include 시켜줍니다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />
  <property name="CONSOLE_LOG_PATTERN" value="%green(%d{yyyy-MM-dd HH:mm:ss.SSS}) %magenta([%thread]) %clr(%5level) %cyan(%logger) - %yellow(%msg%n)" /> <!-- 해당 패턴 네이밍으로 현재 콘솔 로그가 기록됨 -->
  <property name="FILE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %5level %logger - %msg%n" /> <!-- 해당 패턴 네이밍으로 현재 파일 로그가 기록됨 -->

  <include resource="console-appender.xml" />
  <include resource="default-appender.xml" />
  <include resource="error-appender.xml" />
  <include resource="http-appender.xml" />
  <include resource="slack-appender.xml" />

  <logger name="HaruStudyExceptionLogger" level="WARN" additivity="false">
    <appender-ref ref="ERROR"/>
    <appender-ref ref="ASYNC_SLACK_APPENDER"/>
  </logger>

  <logger name="HaruStudyHttpLogger" level="INFO" additivity="false">
    <appender-ref ref="HTTP"/>
  </logger>

  <root level="INFO"> <!-- 전체 프로젝트의 로그 레벨을 설정 -->
    <!-- 여기에 추가되는 Appender들은 root에 설정된 level 로깅을 각자 설정에 맞게 자동으로 수행해준다.   -->
    <appender-ref ref="CONSOLE"/> <!-- 사용하고자 하는 appender 등록 -->
    <appender-ref ref="DEFAULT"/>
  </root>
</configuration>

 

 

다음은 프로젝트 팀 Slack 채널에 Incoming Webhook을 걸어서 알림 메세지 요청을 보낼 url을 생성해야 합니다. Slack Incoming Webhook이란 Slack에서 미리 정해둔 형식으로 데이터 요청이 들어오면 지정된 채널에 메세지를 출력해주는 기능입니다. Incoming Webhook 설정은 다음 레퍼런스를 참고하여 진행하였습니다.

 

Slack Incoming Webhook을 생성 완료하면 메세지 요청을 보낼 URL을 얻을 수 있습니다. 이를 이용해서 본격적으로 프로젝트 팀 Slack 채널에 메세지를 보내는 SlackAppender를 구현해보겠습니다. 다음은 직접 구현한 CustomSlackAppender의 코드입니다.

 

public class SlackAppender extends AppenderBase<ILoggingEvent> {

    public static final String MESSAGE_FORMAT = """
            로그 메세지 본문
            ```%s %s %s [%s] - %s ```
            """;
    public static final String SLACK_INCOMING_WEB_HOOK_URL =
            "https://hooks.slack.com/services/{개인 URL 구분자}";

    @Override
    protected void append(ILoggingEvent eventObject) {
        RestTemplate restTemplate = new RestTemplate();
        Map<String, Object> slackAlertBody = createSlackAlertBody(eventObject); //ILoggingEvent 객체에 담겨있는 로깅 데이터를 메세지로 만들어서
        restTemplate.postForEntity(SLACK_INCOMING_WEB_HOOK_URL, slackAlertBody, String.class); //Slack에 알림 메세지를 전송한다
    }

    private static Map<String, Object> createSlackAlertBody(ILoggingEvent eventObject) {
        String message = createMessage(eventObject);
        return Map.of(
                "blocks", List.of(
                        Map.of(
                                "type", "header",
                                "text", Map.of(
                                        "type", "plain_text",
                                        "text", ":rotating_light: 예상하지 못한 에러가 발생했습니다. 그라파나에서 로그를 확인해주세요!"
                                )
                        ),
                        Map.of(
                                "type", "section",
                                "text", Map.of(
                                        "type", "mrkdwn",
                                        "text", message
                                )
                        ),
                        Map.of(
                                "type", "section",
                                "text", Map.of(
                                        "type", "mrkdwn",
                                        "text", "<http://project.grafana.com|그라파나 바로가기>"
                                )
                        )
                )
        );
    }

    private static String createMessage(ILoggingEvent eventObject) {
        SimpleDateFormat simpleDateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
        return String.format(MESSAGE_FORMAT,
                simpleDateFormat.format(eventObject.getTimeStamp()),
                eventObject.getLevel(),
                eventObject.getThreadName(),
                eventObject.getLoggerName(),
                eventObject.getFormattedMessage());
    }
}

최상단에 작성된 SLACK_INCOMING_WEB_HOOK_URL 을 보실 수 있습니다. 여기에 알림 메세지를 보내고자 하는 slack 채널에 Incoming Webhook을 생성하고 받은 URL을 넣어줍니다. 그리고 append() 메서드를 오버라이딩해서 restTemplate을 이용해 직접 슬랙에 알림 요청을 보냅니다.

 

다른 부분은 슬랙에 출력될 메세지 내용과 형식을 만들어주는 메서드들입니다. eventObject에는 로깅 이벤트가 발생했을 때 입력된 데이터들이 저장되어있어 이를 이용해 메세지 내용을 만들어줍니다. 메세지 형식은 slack에서 제시하는 형식을 지키지 않으면 400 badRequest를 응답으로 주고 알림을 전혀 출력하지 않으므로 Slack 공식 문서에서 제시하는 양식을 잘 지켜서 보내야 합니다.

 

여기까지 모두 완료한 뒤 서버를 실행시켜 에러를 발생시키면 다음과 같이 슬랙에 알림 메세지가 발송됨을 확인할 수 있습니다.

 

Incoming Webhook url로 메세지 요청이 정상적으로 처리됨을 확인할 수 있습니다.

 

이렇게 성공적으로 customSlackAppender를 구현하여 슬랙 알림 기능을 구현하였습니다.

 

 

 


추가사항

 

위에서 작성한 SlackAppender는 상수로 Slack Incoming Webhook URL을 관리하고 있습니다. 이를 로컬에서만 실습용으로 사용할 때는 상관 없으나 github에 push를 하는 순간 보안 문제가 발생하게 됩니다. 만약 github 팀 프로젝트 repository에 security 옵션으로 secret scanning을 설정해뒀다면 자동으로 이를 감지하고 알림을 표시해줍니다.

 

github Security 경고 알림

 

또한 Slack에서는 이렇게 노출된 incomming webhook url을 자동으로 무효화합니다. 또한 이 사실을 사용자에게 고지하기 위한 이메일을 바로 수신할 수 있습니다. 어떻게 알았냐구요? 저도 알고 싶지 않았습니다…

 

믿고 사용하는 Slack인 것 같습니다

 

이를 방지하기 위해 다음과 같이 application.properties 파일을 통해 민감한 url 정보들을 읽어올 수 있도록 수정하면 됩니다. 또한 분리해낸 application.properties 등은 submodule과 같은 방법을 사용하면 외부로 파일을 노출시키지 않고 프로젝트에서 사용하실 수 있습니다.

 

// application.properties 파일로 URL들을 분리한 최종 SlackAppender

import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.AppenderBase;
import java.io.FileReader;
import java.io.IOException;
import java.text.SimpleDateFormat;
import java.util.List;
import java.util.Map;
import java.util.Properties;
import org.springframework.util.ResourceUtils;
import org.springframework.web.client.RestTemplate;

public class SlackAppender extends AppenderBase<ILoggingEvent> {

    public static final String PROPERTIES_PATH =
            "src\\main\\resources\\submodule\\application.properties";

    private static final String MESSAGE_FORMAT = """
            로그 메세지 본문
            ```%s %s %s [%s] - %s ```
            """;

    private static String slackWebhookUrl;
    private static String grafanaUrl;

    static {
        Properties properties = new Properties();
        try {
            FileReader fileReader = new FileReader(ResourceUtils.getFile(PROPERTIES_PATH));
            properties.load(fileReader);
            slackWebhookUrl = properties.getProperty("slack-webhook-url");
            grafanaUrl = properties.getProperty("grafana-url");
        } catch (IOException e) {
            e.printStackTrace();
        }
    }

    @Override
    protected void append(ILoggingEvent eventObject) {
        RestTemplate restTemplate = new RestTemplate();
        Map<String, Object> slackAlertBody = createSlackAlertBody(
                eventObject); //ILoggingEvent 객체에 담겨있는 로깅 데이터를 메세지로 만들어서
        restTemplate.postForEntity(slackWebhookUrl, slackAlertBody,
                String.class); //Slack에 알림 메세지를 전송한다
    }

    private Map<String, Object> createSlackAlertBody(ILoggingEvent eventObject) {
        String message = createMessage(eventObject);
        return Map.of(
                "blocks", List.of(
                        Map.of(
                                "type", "header",
                                "text", Map.of(
                                        "type", "plain_text",
                                        "text",
                                        ":rotating_light: 예상하지 못한 에러가 발생했습니다. 그라파나에서 로그를 확인해주세요!"
                                )
                        ),
                        Map.of(
                                "type", "section",
                                "text", Map.of(
                                        "type", "mrkdwn",
                                        "text", message
                                )
                        ),
                        Map.of(
                                "type", "section",
                                "text", Map.of(
                                        "type", "mrkdwn",
                                        "text",
                                        String.format("<%s|그라파나 바로가기>", grafanaUrl)
                                )
                        )
                )
        );
    }

    private String createMessage(ILoggingEvent eventObject) {
        SimpleDateFormat simpleDateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");
        return String.format(MESSAGE_FORMAT,
                simpleDateFormat.format(eventObject.getTimeStamp()),
                eventObject.getLevel(),
                eventObject.getThreadName(),
                eventObject.getLoggerName(),
                eventObject.getFormattedMessage());
    }
}

 

추가적으로 Logger들을 스프링 Bean으로 등록해서 관리하는 방법을 사용하면 yml 파일로 property를 분리해서 @Value 어노테이션을 통해 값을 주입받아 사용할 수 있을 것 같습니다. 하루스터디 프로젝트에서는 이미 로거들을 POJO로 구현해둬서 위와 같은 방법을 사용했지만 나중에 언젠가는 Logger들을 bean으로 등록해서 관리해보는 것도 좋은 방법일 것 같아 레퍼런스를 추가해둡니다.

 


Reference

 

https://kwonnam.pe.kr/wiki/java/logback

https://kangwoojin.github.io/programing/logback-async-appender/

https://velog.io/@king/slack-incoming-webhook

https://api.slack.com/messaging/composing/layouts#adding-blocks

https://www.baeldung.com/logback

https://www.baeldung.com/custom-logback-appender

https://logback.qos.ch/manual/appenders.html#WriteYourOwnAppender

https://stackoverflow.com/questions/45693107/define-logback-shutdown-hook-in-spring-boot

https://be-student.tistory.com/90