[AWS] CloudWatch + Lambda로 slow query 발생 시 Slack 알림 보내기

해당 글에서는 AWS RDS MySQL 환경에서 CloudWatch, Lambda를 이용합니다.

람다 함수는 Node.js 14 환경에서 작성됐습니다.

---

사이드 프로젝트 `모카콩`의 Wiki에 작성한 글에 해당된다.

---

 

해당 프로젝트 github: https://github.com/mocacong/Mocacong-Backend

GitHub - mocacong/Mocacong-Backend: 모카콩 백엔드

---

들어가며

최근 AWS RDS 환경의 로깅에 대해 생각해보는 시간을 가져봤습니다. 처음에는 RDS에 기록되는 쿼리 전체를 로그로 남겨볼까 하는 생각이 들었는데요. 하지만 운영 RDS(혹은 개발 RDS라 하더라도)에서 general_log 옵션을 켜두는 것은 디스크 용량을 압도적으로 많이 차지하고 불필요한 로그가 남아 오히려 필요한 로그를 확인하기 어렵다는 단점이 존재합니다.

 

그러다가 slow query에 대해서는 로그로 남겨두는 것이 좋겠다는 생각이 들었습니다. 이왕이면 지나치게 느린 쿼리는 유저 입장에서도 답답해할테니 슬랙으로 알림을 보내주어 빨리 개선하라고 채찍질을 해주면 더더욱 좋겠죠! (백엔드 죽어나가는 소리가 여기까지 들리네요 😇)

 

마침 향로(이동욱)님께서 관련 글을 올리신 적도 있기 때문에 jojoldu님의 블로그 포스팅을 참고하면서 세팅을 잘 마무리할 수 있었습니다.

https://jojoldu.tistory.com/711

AWS RDS PostgreSQL에서 Slow, Error, DDL 쿼리 발생시 Slack 발송하기

다만, 향로님께서는 Node 18 환경으로 작성하셨습니다. 저는 Node 18 문법이 약해서 Node 14 문법으로 lambda 함수를 작성하였습니다. 또, Slack Message 형식은 개인적으로 이쁘다고 생각되는 저만의 형식으로 따로 커스터마이징했습니다.

---

1. AWS RDS 세팅

파라미터 그룹 수정

• slow_query_log: 1
  • 1로 설정해두어야 slow_query를 log로 남깁니다.
• long_query_time = 5
  • 5초 넘게 실행되는 쿼리 로그
• slow_query_log_file = slow query log를 저장할 경로와 이름
  • default: /rdsdbdata/log/slowquery/mysql-slowquery.log
  • 저는 기본 옵션으로 설정해놨습니다.
• log_output: FILE
  • Cloudwatch 에 로그 파일을 남기기 위한 목적

 

RDS 설정 수정

RDS 인스턴스 접속 -> 수정

파라미터 그룹 설정 직후에는 수정이 불가할 수 있습니다.

기존에는 로그 내보내기 옵션을 아무것도 체크하지 않았습니다. 하지만 지금은 slow query를 로그로 남기려 하는 것이므로 아래 그림처럼 RDS 인스턴스를 수정하고 바로 적용했습니다.

 

설정을 마친 후에는 재부팅을 해주어야 합니다. 모카콩은 HA가 이루어지지 않은 단일 DB 환경이었어서 재부팅 동안 DB가 멈추는 문제점이 있었는데요. 다행히 해당 시간에 작업을 하는 팀원이 없었고, 모카콩은 아직 앱 배포를 하지 않았기 때문에 부담없이 재부팅할 수 있었습니다. (나중에 replication-db를 설정해두어야겠다는 생각이 드네요.)

 

설정 이후 Cloudwatch에 slow query가 로그로 남는지 확인해보았습니다.

select sleep(6);

RDS 인스턴스 - 구성으로 들어가면 로그 이벤트를 확인할 수 있습니다.

성공적으로 로그에 남는군요. CloudWatch 환경에서 직접 보고 싶다면 우측 가운데에 빨간 박스로 칠해둔 느린 쿼리를 클릭하시면 됩니다.

---

2. Slack Webhook URL 생성

슬랙 알림을 보내줄 채널을 생성, 혹은 접속합니다.

이후에 해당 채널을 우클릭하여 아래 프로세스대로 들어가줍니다.

채널 세부정보 보기 → 통합 → 앱 → 앱 추가

 

앱 추가에서 incoming webhook 을 추가해줍시다.

여기서 보이는 웹후크 URL로 슬랙 채널을 식별하므로 잘 기억해두거나 복사해두도록 합시다.

---

3. Lambda 함수 작성

이제 작성된 로그를 슬랙 메시지로 보내주는 트리거를 설정해주기 위해 lambda 함수를 작성해보려 합니다. lambda 함수는 별도의 객체지향이 필요없으므로 java 보다는 js나 python으로 작성하는 것을 선호하는 편입니다. (개인적으로는 알고리즘이랑은 또 다른 느낌이라 생각해 C, C++은 또 거부감이 느껴졌습니다 😥) 따라서 저는 Nodejs로 작성했는데요, Node 18 환경으로 람다 함수를 작성하니 문법적 차이 때문인지 에러가 발생했습니다.

 

처음에는 Node 18 환경만 지원해주는 것으로 착각하여 걱정이 많았는데, 다행히 이전 버전도 지원해주었습니다! 그렇기 때문에 저는 위 사진처럼 Nodejs 14 환경에서 진행했습니다. 그리고 다행히 향로님이 예전에 작성하신 Node 14 람다함수 코드가 있어서 이를 참고하여 잘 작성할 수 있었습니다.

index.mjs

const https = require('https');
const zlib = require('zlib');
const SLOW_TIME_LIMIT = 5; // 5초이상일 경우 슬랙 발송
const SLACK_URL = '슬랙 WEBHOOK URL'; // slack webhook url
 
// 로그 발생 시 슬랙으로 알림을 보내도록
exports.handler = (input, context) => {
  const payload = Buffer.from(input.awslogs.data, 'base64');
  zlib.gunzip(payload, async (e, result) => {
 
    if (e) {
      context.fail(e);
    }
 
    const resultAscii = result.toString('ascii');
 
    let resultJson;
 
    try {
      resultJson = JSON.parse(resultAscii);
    } catch (e) {
      console.log(`[알람발송실패] JSON.parse(result.toString('ascii')) Fail, resultAscii= ${resultAscii}`);
      context.fail(e);
      return;
    }
 
    console.log(`result json = ${resultAscii}`);
 
    for (let i = 0; i < resultJson.logEvents.length; i++) {
      const logJson = toJson(resultJson.logEvents[i], resultJson.logStream);
      console.log(`logJson=${JSON.stringify(logJson)}`);
 
      try {
        const message = slackMessage(logJson);
 
        if (logJson.queryTime > SLOW_TIME_LIMIT) {
          await exports.postSlack(message, SLACK_URL);
        }
      } catch (e) {
        console.log(`slack message fail= ${JSON.stringify(logJson)}`);
        return;
      }
 
    }
  });
};
 
// 로그에 기록되는 메시지 형식 파싱
const toJson = (logEvent, logLocation) => {
  const message = logEvent.message;
 
  const splitMessages = message.split("#");
  const userInfos = splitMessages[2].split(" ");
  const queryInfos = splitMessages[3];
  const queryTime = queryInfos.split(" ")[2];
  const currentTime = toYyyymmddhhmmss(logEvent.timestamp);
  const queryMessages = queryInfos.split(";");
  const queryMessage = queryMessages[queryMessages.length - 2];
 
  return {
    "currentTime": currentTime,
    "logLocation": logLocation,
    "userIp": userInfos[5],
    "user": userInfos[2],
    "pid": userInfos[8],
    "queryTime": queryTime,
    "query": queryMessage
  }
}
 
// 타임존 UTC -> KST 
// 2023-04-21 15:12:39.123
const toYyyymmddhhmmss = (timestamp) => {
 
  if (!timestamp) {
    return '';
  }
 
  function pad2(n) { return n < 10 ? '0' + n : n }
 
  const kstDate = new Date(timestamp + 32400000);
  return kstDate.getFullYear().toString()
    + '-' + pad2(kstDate.getMonth() + 1)
    + '-' + pad2(kstDate.getDate())
    + ' ' + pad2(kstDate.getHours())
    + ':' + pad2(kstDate.getMinutes())
    + ':' + pad2(kstDate.getSeconds())
    + '.' + pad2(kstDate.getMilliseconds().toPrecision(3));
}
 
// 슬랙 메시지 형식
const slackMessage = (messageJson) => {
  return {
    text: 'Slow Query 발생!',
    attachments: [
      {
        color: '#ff7f00',
        title: `${messageJson.currentTime} 발생 Slow Query`,
        fields: [
          {
            title: 'Query',
            value: `${messageJson.query}`,
            short: false
          },
          {
            title: 'Query Time',
            value: `${messageJson.queryTime}`,
            short: false
          },
          {
            title: 'Log Location',
            value: `${messageJson.logLocation}`,
            short: false
          },
          {
            title: 'Request User',
            value: `${messageJson.user}`,
            short: false
          },
          {
            title: 'Request IP',
            value: `${messageJson.userIp}`,
            short: false
          }
        ]
      }
    ]
  };
}
 
exports.postSlack = async (message, slackUrl) => {
  return await request(exports.options(slackUrl), message);
}
 
exports.options = (slackUrl) => {
  const { host, pathname } = new URL(slackUrl);
  return {
    hostname: host,
    path: pathname,
    method: 'POST',
    headers: {
      'Content-Type': 'application/json'
    },
  };
}
 
const request = (options, data) => {
 
  return new Promise((resolve, reject) => {
    const req = https.request(options, (res) => {
      res.setEncoding('utf8');
      let responseBody = '';
 
      res.on('data', (chunk) => {
        responseBody += chunk;
      });
 
      res.on('end', () => {
        resolve(responseBody);
      });
    });
 
    req.on('error', (err) => {
      console.error(err);
      reject(err);
    });
 
    req.write(JSON.stringify(data));
    req.end();
  });
}

슬랙에 알림을 보내는 요청 관련 코드는 향로님 포스팅을 많이 참고했습니다.

주의할 점은 향로님은 PostgreSQL 환경에서, 제가 작성한 람다함수는 MySQL 환경에 맞게 작성됐다는 점입니다. 따라서 toJson 함수는 많이 다를 수 있습니다.

 

slow query 발생 시 슬랙에 뜨는 메시지

또, 슬랙 메시지 형식을 위 사진처럼 커스터마이징하고 싶었습니다. 그렇기 때문에 slackMessage 함수도 추가로 작성한 로직이 존재해 비교적 복잡합니다. 슬랙 메시지 구조에 대해 궁금하시다면 아래 포스팅을 참고해주세요. https://kth990303.tistory.com/438 

[Spring] 서버 에러 시 Slack Api Client로 슬랙에 알림 보내기

그 외 차이점으로는 slow query 발생 시간을 miliseconds 까지 기록되게 한 점이 있습니다.

 

 

MySQL 기준으로 기록되는 로그 메시지 형태는 아래와 같습니다.

# Time: 2023-04-21T06:40:19.587857Z
# User@Host: kth990303[kth990303] @  [123.45.14.12]  Id:    13
# Query_time: 6.002466  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
use abcdef;
SET timestamp=1682059213;
/* ApplicationName=DataGrip 2022.2.4 */ select sleep(6);

Lambda 함수를 우리가 잘 작성해주었는지 테스트를 해봅시다. 우리는 위 로그 텍스트 데이터를 람다 함수를 통해 슬랙에 보내주고 싶습니다. 하지만 그러려면 이 텍스트 형식을 gZip으로 압축해준 후에 람다 함수에 넘겨주어야 합니다. gZip 압축은 아래 사이트에서 진행할 수 있습니다.

https://www.multiutil.com/text-to-gzip-compress/

위 데이터를 압축하면 아래와 같은 json 형식 데이터로 변환됩니다.

{
  "awslogs": {
    "data": "H4sIAAAAAAAACi2PX0vDQBDE3/MpFvqihV5vN5dreqFQQdGCCGp8sZRyJisE8+fIXdF+ey/VeViYgZkfO4Oy6dgASUoXUi0IS6mNkgbXIstXebZ6T2bw5nncPgw+GLB11/T7yz3AFmCPlAqVCVQC6QCwqw1EYRprzycez8dwAWghJSmtAR6H6us/lDGcBC/Dtz967iMA4c/xj40MjnOYnDyD/ahq/iyS17sSprYPtnMb1DnJbE2YFslyDjfOtU1lQzP0T7bjza0N9n5s3PQfCRIK5kvw3HIVwLfM7kpfF79TrV/HBAEAAA=="
  }
}

이 값을 기준으로 우리가 작성한 람다함수 코드에 에러는 없는지 테스트해볼 수 있습니다.

참고로 테스트할 때 람다 함수 코드가 수정이 됐다면 저장을 누르고 테스트를 해야, 수정본으로 테스트가 됩니다.

 

(근데 저의 경우에는 분명 에러가 없음에도 불구하고 계속 에러가 뜬다고 해서, 결과를 무시하고 deploy 누르긴 했습니다. 실제 실행에도 문제가 없어 넘어갔습니다.)

---

4. CloudWatch 로그 그룹에 Lambda 함수 구독하기

이제 람다 함수 작성을 마쳤으니, CloudWatch와 연동하여 해당 로그 그룹에 로그가 쌓이면 Lambda 함수가 작동되도록 해봅시다.

CloudWatch - slow query 로그 그룹 접속

설정한 로그 그룹에 접속하여 `구독 필터` - `Lambda 구독 필터 생성`을 클릭해주고, 자신이 설정해둔 lambda 함수를 선택합니다.

 

그러면 끝납니다!

Datagrip에서 sleep 쿼리 등으로 테스트를 통해 슬랙에 알림이 보내지고,

CloudWatch에도 데이터가 잘 쌓이는 것을 확인할 수 있습니다~

 

참고

• https://imweb.me/blog?idx=72
• https://jojoldu.tistory.com/711
• https://jojoldu.tistory.com/570
• https://velog.io/@yyong3519/RDS-Slow-%EC%BF%BC%EB%A6%AC-Slack%EC%9C%BC%EB%A1%9C-%EC%95%8C%EB%9E%8C-%EB%B3%B4%EB%82%B4%EA%B8%B0