AWS 람다 로그 잘 남기고 추적하기(AWS Lambda Logging)

13 min readFeb 8, 2019

프로그래밍에서 로깅(Logging)은 언제나 필수적이다. 적재적소에 알맞는 로그 메시지를 넣는 행위는 개발자에게 개발 및 디버깅에 편의를 제공해 줄 수 있다.

물리적인 파일 시스템(file-system)에 로그 파일을 생성하고 로그를 기록하던 개발자에게는 서버-리스(Severless)라는 실체가 없이 추상화된 환경에서의 로그 추적은 생소한 일이다. 필자도 처음 람다(Lambda)를 사용하면서 어려웠던 점 중 하나가 이 부분이 었다. 기본적으로 클라우드-와치(CloudWatch) 콘솔에서 텍스트 로그를 제공하고 있지만, 터미널(Terminal) 환경에서 grep과 tail 등 명령어를 이용해서 로그를 추적하던 개발자들에게는 불편함을 안겨다 줄 것이다.

그러나, 사실 람다-로깅은 개발자를 대신해서 많은 일을 해주고 있다. 예를 들어 여러 개의 EC2로 분산된(Distributed) 서비스 환경을 상상해보자. 이때 로그를 추적하는 방법으로 가장 직관적인 방법은 각각의 EC2에 접속하여 로그를 확인하는 방법이다. 그러나 분산환경의 스케일이 커질수록 이는 점점 불가능에 가까워질 것이다. 다른 대안으로는 중앙관리 로깅(Centralized logging)환경을 구성하는 방법이지만 이도 쉽지만은 않다. 하지만 서버-리스 람다의 경우 이러한 일을 람다와 클라우드-와치가 대신해줌으로써 개발자는 별도의 환경구성이나 람다의 스캐일(Scale)과 상관없이 정형화되고 일관된 방법으로 로그를 추적할 수 있다.

이 포스팅은 처음 람다는 사용하는 개발자를 위해 람다-로깅에 대해 간단하게 알아본다. 기본 예제는 코드는 파이썬을 사용하였으며, 테스트를 위한 람다 호출은 AWS Cli lamba invoke를 활용하였다.

클라우드-와치 로그 롤(Role)

람다에서 클라우드-와치 로그를 기록하기 위해서는 람다에 명시적인 권한 부여가 필요하다. 아래의 롤을 생성하여 람다에게 부여하자.

{
    "Version": "2012-10-17",
    "Statement": [
        {
            "Action": [
                "logs:CreateLogStream",
                "logs:PutLogEvents"
            ],
            "Resource": [
                "arn:aws:logs:${region}:${account}:log-group:/aws/lambda/${function}"
            ],
            "Effect": "Allow"
        }
    ]
}

로그-그룹(Log Groups)과 로그-스트림(Log Streams)

하나의 람다-함수는 하나의 로그-그룹에 로그를 기록한다. 로그-그룹이름은 람다-함수 이름에 따라 다음과 같은 형태를 갖는다.

/aws/lambda/${function_name}

로그-그룹생성 시점은 람다함수 생성시점이 아닌, 최초 람다가 로그를 기록할 때이다. 로그 기록이란 stdout 또는 stderr에 문자열을 출력함을 뜻 한다. 람다-함수가 로그 기록을 시도하더도 앞서 설명한 롤-권한이 없다면 로그-그룹은 생성되지 않는다.

로그-그룹은 하나 이상의 로그-스트림으로 이루어져 있다. 람다는 내부적으로 동시-실행(Concurrent Execution)라고 불리는 작은 인스턴스 단위로 이루어져 있다. 람다는 동시-실행 개수만큼 병렬실행을 지원하며, 각각의 동시-실행은 하나의 로그-스트림에 순차적으로 로그를 기록한다.

람다는 발생하는 트래픽의 증가와 감소에 따라 새로운 동시-실행의 생성 및 파괴를 반복한다(Auto-Sclaing). 새로운 동시-실행이 생성되면 그에따라 새로운 로그-스트림이 생성되며 동시-실행이 파괴되면 해당 로그-스트림에 더 이상 로그가 기록되지 않는다.

AWS Logging Tool `awslogs`

awslogs는 터미널 환경에서 손쉽게 클라우드-와치 로그 추적을 돕는 파이썬 기반의 오픈소스이다. 다양한 필터 옵션을 제공하며 터미널 명령어들과 파이프(pipe)하여 사용할수 있다. 람다 로그뿐만 아니라 클라우드-와치의 로그 모두 같은 방법으로 추적이 가능하다.

# list log-groups
$ awslogs groups
# list log-streams in ${log-group}
$ awslogs streams ${log-group}
# print all log-stream logs in ${log-group}
$ awslogs get ${log-group}
# print ${log-stream} log
$ awslogs get ${log-group} ${log-stream}
$ awslogs get ${log-group} \
    --profile default \  # specify aws profile
    --watch \      # tail logs
    --timestamp \  # print timestamp
    --start 2h \   # print logs 1h before only      
    --end 1h \     # print logs 2h after only  
    -f 'test' \    # print log including 'test' string only
    -S  # not print log-stream name
    -G  # not print log-group name

AWS Cli를 처음 사용하는 경우 다음의 선행 절차를 따라 설정을 진행해야 한다.

람다 Request ID

def handler(event, context):
    print('lambda log messge')

간단한 메시지를 출력하는 람다-함수이다. 함수를 실행시키고 로그 메시지를 확인해보자.

$ awslogs get /aws/lambda/test-function -S -G --watch
START RequestId: c060f0f6-ca41-4369-aedb-06afdbd7eec6 Version: $LATEST/aws/lambda/test-functionlambda log messageEND RequestId: c060f0f6-ca41-4369-aedb-06afdbd7eec6/aws/lambda/test-functionREPORT RequestId: c060f0f6-ca41-4369-aedb-06afdbd7eec6    Duration: 0.40 ms       Billed Duration: 100 ms  Memory Size: 128 MB    Max Memory Used: 22 MB

출력 메시지 이외에 START, EDN 그리고 REPROT 구문이 추가적으로 출력됨을 확인할 수 있다.

START: 함수-호출 시작 시 출력된다.
END: 함수-호출 종료 시 출력된다. 종료는 정상적인 종료와 타임아웃(time-out) 및 에러와 같이 비정상적인 종료를 포함한다.
REPORT: 함수-호출 종료이후 함수-호출 수행시간, 그에 따른 청구시간 그리고 사용 메모리가 출력된다.

이들 구문(START, END, REPORT)은 동일하게 RequsetId를 함께 출력하고 있다. RequsetId는 연속적으로 요청되는 람다-함수 호출속에서 특정 함수-호출을 구분하는 고유 값이다. START, END, REPORT구문은 같은 RequestID를 함께 출력함으로써 동일함수-호출의 로그임을 인지할 수 있다. RequsetId는 람다-함수 context.aws_request_id 파라메터에 접근하여 얻을 수 있다.

Request ID를 활용하여 특정 함수-호출 로그 필터

import timedef handler(event, context):
    time.sleep(10)  
    msg = event['key']  
    print('RequestId(%s): %s' % (context.aws_request_id, msg))

2개의 터미널을 열어 아래의 명령어를 통해 동시에 람다-함수를 호출해보자. 2개의 함수호출은 다른 payload를 가지고 있음을 주목하자.

$ aws lambda invoke --function-name lambda-test-api-test --payload '{"key": "ERROR"}' testout.txt--------------------------------------------------------------------$ aws lambda invoke --function-name lambda-test-api-test --payload '{"key": "OK"}' testout.txt

첫 번째 함수가 끝나기 전에 두 번째 함수가 호출됨으로써 2개의 동시-실행이 병렬적으로 실행된다(2개의 동시-실행은 서로 다른 로그-스트림에 로그를 기록한다).

$ awslogs get /aws/lambda/test-function -S -G --watch
START RequestId: e98bee50-47bd-be65-b2f4c8d3e604 Version: $LATESTSTART RequestId: 40d70cd1-49a2-88b1-3b5dd5d3b112 Version: $LATESTRequestId(e98bee50-47bd-be65-b2f4c8d3e604): ERROREND RequestId: e98bee50-47bd-be65-b2f4c8d3e604REPORT RequestId: e98bee50-47bd-be65-b2f4c8d3e604  Duration: 5005.46 ms    Billed Duration: 5100 ms        Memory Size: 128 MB     Max Memory Used: 22 MBRequestId(40d70cd1-49a2-88b1-3b5dd5d3b112): OKEND RequestId: 40d70cd1-49a2-88b1-3b5dd5d3b112REPORT RequestId: 40d70cd1-49a2-88b1-3b5dd5d3b112  Duration: 5005.49 ms    Billed Duration: 5100 ms        Memory Size: 128 MB     Max Memory Used: 22 MB

2개의 함수-호출 로그가 뒤섞여 출력되고 있다. 특정 함수-호출의 로그만을 보려고 하면 어떻게 해야 할까? 예를들면 ERROR를 payload로 가지고 있는 함수-호출의 로그만을 구분해 보자. 예제에서는 2개의 간단한 함수-호출이기에 눈으로 식별이 가능하지만 수 십-수 백개의 함수가 동시에 호출되었다고 한다면 눈으로 구별하기 어려움이 있을 것이다. 앞서 RequsetId를 각각의 함수-호출을 구분하는 고유 값이라고 언급하였다. 필터기능에 RequsetId를 넣어 로그를 출력해보자.

$ awslogs get /aws/lambda/test-function -S -G --watch -f 'e98bee50'START RequestId: e98bee50-47bd-be65-b2f4c8d3e604 Version: $LATESTRequestId(e98bee50-47bd-be65-b2f4c8d3e604): ERROREND RequestId: e98bee50-47bd-be65-b2f4c8d3e604REPORT RequestId: e98bee50-47bd-be65-b2f4c8d3e604  Duration: 5005.46 ms    Billed Duration: 5100 ms        Memory Size: 128 MB     Max Memory Used: 22 MB

함수-호출의 RequsetId를 필터로 사용하여 원하는 특정 함수-호출 로그만을 필터하여 확인할 수 있다.

람다-함수는 이벤트-소스(event-source)에 따라 다른 재시도 정책을 따른다. 그 중 비동기식 호출방식은 람다-함수 실패시 2번의 재시도를 수행하며 재시도된 함수-호출은 이전의 함수-호출과 같은 RequestId를 갖는다. 이러한 경우 RequestId를 조건으로한 필터를 통해 재시도 되는 함수-호출까지 함께 추적할 수 있다.
대표적인 비동기식 호출방식은 S3 Event Notifiction과 SNS Subscription이 있다.

Requset ID를 활용한 로거(Logger)

RequsetId를 모든 로그 메시지와 함께 출력함으로써 개별 함수-호출을 손쉽게 추적할 수 있다. 로거 모듈을 활용하여 모든 로그 메시지에 RequsetId를 함께 출력하도록 하자.

import loggingdef handler(event, context):
    logger = logging.getLogger(context.aws_request_id)
    logger.setLevel(logging.DEBUG)
    logger.info('logger message')

로거 오프젝트 이름을 함수-호출의 RequsetId로 지정하여 로거를 이용한 모든 메시지 출력은 RequsetId를 포함하도록 하였다.

$ awslogs get /aws/lambda/test-function -S -G --watch -fSTART RequestId: e2b2c880-f8c7-4593-b19a-4a1449581b93 Version: $LATEST[INFO]  2019-02-03T08:57:57.250Z        e2b2c880-f8c7-4593-b19a-4a1449581b93    logger messageEND RequestId: e2b2c880-f8c7-4593-b19a-4a1449581b93REPORT RequestId: e2b2c880-f8c7-4593-b19a-4a1449581b93  Duration: 0.42 ms       Billed Duration: 100 ms         Memory Size: 128 MB     Max Memory Used: 22 MB

이렇게 구성된 로그 환경에서 람다 운영중 발생하는 에러를 추적하기 위해 다음과 같은 절차를 따른다.

클라우드-와치 ERROR 매트릭(Metric) 또는 알람을 통해 에러를 인지한다.
매트릭에 표시된 대략의 시간과 에러 메시지 필터를 사용하여 에러메시지를 확인한다.

$ awslogs get /aws/lambda/test-function -s 4h -e 3h -f ERROR

3. 출력된 에러 메시지의 RequsetId를 확인한다.

4. RequsetId 필터를 통해 전체 함수-호출 및 재시도 로그를 확인한다.

$ awslogs get /aws/lambda/test-fucntion -s 4h -e 3h -f ${request_id}

마치며…

지금까지 람다-로깅에 대해서 알아보았다. 핵심 된 내용은 “수많은 동시-실행에 의해 생성되는 일련의 로그-기록 속에서 내가 원하는 내용을 빠르게 찾을 수 있어야 한다.” 이다. 이를 위한 하나의 방법으로 Request ID를 활용한 방법을 중점적으로 이야기하였지만, 이벤트-소스에 따라 인지해야하는 다양한 값들이 존재하면 알맞은 로깅을 위해서 다른 접근방법이 필요할 수 있다. (예를 들면 SQS의 message_id와 receipt_handler 값이 있다.) 따라서 나의 목적과 사용하는 이벤트-소스 성격을 파악하고 알맞은 형식의 로그를 남기는 것이 필요하다.