Python AWS Powertools log 날짜포맷 변경하기

개요

• 3개의 프로젝트가 있는데 로그의 로그시간 부분의 키와 포맷이 각각 달랐다. 어느쪽이건 키와 포맷을 일치시키고 싶다.

프로젝트	환경	키	포맷(실제값)
A	Python Powertools	timestamp	2023-08-04 02:32:41,872+0000
B	Java logback	date	2023-07-03T17:28:48.377+09:00
C	Java logback	eventTime	2023-06-30 07:10:38.923

• logback은 전체 포맷을 지정해 놓아서 기존 포맷을 그냥 고치면 되는데,
  Powertools의 경우에는 디폴트값을 이용하기 때문에 내가 원하는대로 표시하기 위해 조사하였다.
• timestamp키의 포맷만 바꾸는 경우, timestamp가 아닌 키로 바꾸는 경우, 전체 포맷을 바꾸는 경우에 대해 설명한다.

---

기존 로그 출력 확인

• 우선 지금 출력되고 있는 내용을 확인한다.

{
  "level": "DEBUG",
  "location": "scope:100",
  "message": "DB: yield session",
  "timestamp": "2023-08-04 02:34:41,710+0000",
  "service": "base",
  "xray_trace_id": "X-XXcc63c1-537bae924dfb5b02369a427e"
}

• 다음은 Powertools의 기본 출력내용을 확인한다.
  https://github.com/aws-powertools/powertools-lambda-python/blob/develop/docs/core/logger.md#standard-structured-keys

• level부터 xray_trace_id까지는 출력되었고 sampling_rate부터 exception까지는 출력되지 않았다.
  sampling_rate는 enabled설정을해야 나오고
  exception은 exception이 발생해야 나올것으로 보인다.

---

timestamp키의 포맷만 변경 - datefmt설정

• 포맷은 바뀌나 키가 안 변한다. 키를 그대로 쓴다면 성공 케이스지만, 키도 변경해야하면 실패 케이스.
• 방법: Logger생성시 datefmt에 원하는 포맷 지정
  • 관련 링크: https://docs.powertools.aws.dev/lambda/python/1.28.0/core/logger/#overriding-log-records
• 코드

logger = Logger(service="default", datefmt='%Y-%m-%d %H:%M:%S.%F%z')
logger.info("message_contents")

• 출력

(실제는 1줄에 출력되지만 보기 편하게 하기위해 편집함)
{
  "level":"INFO",
  "location":"<module>:51",
  "message":"message_contents",
  "timestamp":"2023-08-09 00:58:34.615+0900",
  "service":"default"
}

• 오프셋이 자바버전("+09:00")과 다르게 콜론이 빠진 ("+0900")이다.
  • 포맷만으로 변경은 힘들기 때문에 오프셋도 변경하려면 전체 포맷을 바꾸는 방법을 써야한다.
• datetime에서 지원하지 않는 %F라는 지시자에 대해
  • 파이썬 datetime에서는 밀리초는 지원하지 않는다.
  • 밀리초를 표현하고 싶으면 마이크로초를 구하여 1,000으로 나누어 사용해야한다.
  • 마이크로초는 %F이 아닌 %f이다.
  • 그런데 %F를 쓰니 제대로 마이크로초가 나왔다.
  • 그 이유는 Powertools의 formatter에서 커스텀 지시자 '%F'에 대한 코드를 넣어두었기 때문이다.
  • 관련코드를 보자. 중요한 부분만 발췌하였다.
    • 위에서 '%Y-%m-%d %H:%M:%S.%F%z'인 포맷을 지정하였는데,
      %F를 실제 밀리초로 치환하여,
      현시간이 97밀리초라면 '%Y-%m-%d %H:%M:%S.097%z'인 포맷으로 바꾸고 그 포맷을 이용하였다.

class LambdaPowertoolsFormatter(BasePowertoolsFormatter):
    """AWS Lambda Powertools Logging formatter.

    Formats the log message as a JSON encoded string. If the message is a
    dict it will be used directly.
    """

    default_time_format = "%Y-%m-%d %H:%M:%S,%F%z"  # '2021-04-17 18:19:57,656+0200'
    custom_ms_time_directive = "%F"
    
    
    def formatTime(self, record: logging.LogRecord, datefmt: Optional[str] = None) -> str:
        # NOTE: Python `time.strftime` doesn't provide msec directives
        # so we create a custom one (%F) and replace logging record ts
        # Reason 2 is that std logging doesn't support msec after TZ
        msecs = "%03d" % record.msecs
        
        custom_fmt = datefmt.replace(self.custom_ms_time_directive, msecs)
        return time.strftime(custom_fmt, record_ts)

 

---

timestamp가 아닌 키로 변경 - LambdaPowertoolsFormater 오버라이딩

 

 

• 포맷도 바뀌고 키도 바뀌는데 바뀐 키는 가장 뒤로 가버린다.
• 방법: LambdaPowertoolsFormater를 상속받아 serialize함수를 오버라이딩한다.
  • json serialize직전에 값을 빼고 넣는 방식이다.
    • (당연한 얘기지만)키는 가장 뒤로 이동되어버린다.
  • 위의 방식에서는 logger에 datefmt를 설정하였지만, 이 방식에서는 formatter에 설정하였다.
  • 관련링크: https://docs.powertools.aws.dev/lambda/python/1.28.0/core/logger/#bring-your-own-formatter
• 코드

class CustomLambdaFormatter(LambdaPowertoolsFormatter):
    def serialize(self, log: dict) -> str:
        """Serialize final structured log dict to JSON str"""
        log["eventTime"] = log.pop("timestamp")  # rename message key to event
        return self.json_serializer(log)
        
        
custom_lambda_formatter = CustomLambdaFormatter(
    service="custom_lambda_logger_test",
    datefmt='%Y-%m-%d %H:%M:%S.%F%z',
    log_record_order=["level", "location", "message", "eventTime", "service", "x_ray_trace_id", "other"])
    
custom_lambda_logger = Logger(
    logger_formatter=custom_lambda_formatter,
)

@custom_lambda_logger.inject_lambda_context
def lambda_logger_handler(event, context):
    kwargs = {"x_ray_trace_id": "1111111", "other": "other", "another": "another"}
    custom_lambda_logger.logger_formatter.append_keys(**kwargs)
    custom_lambda_logger.info("Collecting payment")


test_context = LambdaContextModel()
test_context.memory_limit_in_mb = 1
test_context.invoked_function_arn = ""
test_context.aws_request_id = "reqId_1"

lambda_logger_handler("{}", test_context)

• 출력

(실제는 1줄에 출력되지만 보기 편하게 하기위해 편집함)
{
  "level":"INFO",
  "location":"lambda_logger_handler:31",
  "message":"Collecting payment",
  "service":"custom_lambda_logger_test",
  "x_ray_trace_id":"1111111",
  "other":"other",
  "cold_start":true,
  "function_name":"UNDEFINED",
  "function_memory_size":1,
  "function_arn":"",
  "function_request_id":"reqId_1",
  "another":"another",
  "eventTime":"2023-08-09 02:35:47.897+0900"
}

• 출력에 대해
  • level부터 other까지는 log_record_order에 설정한 순서대로 출력이 되었다.
  • cold_start부터 function_request_id까지는 아마도 inject_lambda_context에서 설정할 것이다.
  • another는 로그를 찍기전에 설정한 키라서 eventTime을 제외하고 가장 마지막 키가 되었다.
  • eventTime은 json문자열이 되기 직전에 넣은 키이기 때문에 가장 마지막 키가 되었다.
• 굳이 키 위치를 조정하려면 원하는 순서대로 log:dict에 다시 뺐다 넣으면 될 것 같다.

 

---

전체 포맷을 변경 - BasePowertoolsFormatter 오버라이딩

• 좀더 세밀하게 커스터마이징이 가능해졌지만 오버라이딩할 코드가 많다.
  • 예제의 코드 그대로 사용하면 값이 null인 상태의 로그가 출력된다.
  • LogRecord안의 여러가지 값을 로그에 이용할 수 있다.
• 방법: BasePowertoolsFormater를 상속받아 생성자, append_keys, remove_keys, clear_state, format함수를 오버라이딩한다.
  • 관련링크: https://docs.powertools.aws.dev/lambda/python/1.28.0/core/logger/#bring-your-own-formatter
• 코드

class CustomBaseFormatter(BasePowertoolsFormatter):
    def __init__(self, *args, **kwargs):
        self.log_record_order = ["level", "location", "message", "eventTime", "service", "x_ray_trace_id", "other"]
        self.log_format = dict.fromkeys(self.log_record_order)
        super().__init__(*args, **kwargs)

    def append_keys(self, **additional_keys):
        # also used by `inject_lambda_context` decorator
        self.log_format.update(additional_keys)

    def remove_keys(self, keys: Iterable[str]):
        for key in keys:
            self.log_format.pop(key, None)

    def clear_state(self):
        self.log_format = dict.fromkeys(self.log_record_order)

    def format(self, record: logging.LogRecord) -> str:  # noqa: A003
        """Format logging record as structured JSON str"""
        return json.dumps(
            {
                **self.log_format,
                "level": record.levelname,
                "location": f'{record.funcName}:{record.lineno}',
                "message": super().format(record),
                "eventTime": self.formattedTimeStamp(record.created),
                "service": record.name
            },
            separators=(',', ":")
        )

    def formattedTimeStamp(self, timestamp):
        tzinfo = datetime.now().astimezone().tzinfo
        created_datetime = datetime.fromtimestamp(timestamp, tz=tzinfo)
        return f'{created_datetime.strftime("%Y-%m-%d %H:%M:%S")}' \
               f'{created_datetime.strftime(".%f")[:4]}' \
               f'{created_datetime.strftime("%z")[:3]}' \
               f':{created_datetime.strftime("%z")[3:]}'


custom_base_logger = Logger(service="custom_base_logger_test", logger_formatter=CustomBaseFormatter())


@custom_base_logger.inject_lambda_context
def handler(event, context):
    kwargs = {"x_ray_trace_id": "1111111", "other": "other", "another": "another"}
    custom_base_logger.logger_formatter.append_keys(**kwargs)
    custom_base_logger.info("Collecting payment")


handler("{}", test_context)

• 코드에 대해
  • 예제 코드에서는 formatter생성시 log_record_order를 파라미터로 받을 수 있게 하였으나,
    어차피 로그의 순서가 코드마다 바뀌는게 더 이상하다고 생각해 고정값으로 하였다.
  • 예제 코드에서는 json.dump시 **self.log_format이 마지막에 들어가있으나,
    log_format은 키는 있고 값은 없는 상태이다.
    가장 뒤에 있으면 이미 설정한 값이 사라질 수 있으니 주의.
• 출력

(실제는 1줄에 출력되지만 보기 편하게 하기위해 편집함)
{
  "level":"INFO",
  "location":"handler:90",
  "message":"Collecting payment",
  "eventTime":"2023-08-09 03:13:21.083+09:00",
  "service":"custom_base_logger_test",
  "x_ray_trace_id":"1111111",
  "other":"other",
  "cold_start":true,
  "function_name":"UNDEFINED",
  "function_memory_size":1,
  "function_arn":"",
  "function_request_id":"reqId_1",
  "another":"another"
}

• 출력에 대해
  • eventTime이 원하는 위치에 있고 오프셋에 콜론도 표시되었다.

---

결론

• 아직 실제 코드에 대응하진 않았지만, 조금씩 통일성을 갖춰가고 있어서 마음에 든다.
• 3가지 방법 중에 하나를 고르라면 역시 그냥 포맷만 변경하는게 좋을 것 같다.
  정해지지 않은 프로젝트 기준보다는 많은 사람이 쓰는 기준을 따르는 게 나중에 신입이 들어와도 찾아보기 더 쉬울 것이다.
• 한가지 걸리는 것이 있다면 AWS로그를 CSV로 다운 받을 때 헤더인 timestamp가 있고 여기 나오는 timestamp는 message안에 있다는 것. 같은 이름을 써도 헷갈리지 않을까?

---

참고

powertools 포맷 확인:

https://github.com/aws-powertools/powertools-lambda-python/blob/develop/docs/core/logger.md#standard-structured-keys

 

파이썬 datetime 포맷코드 확인:

https://docs.python.org/3/library/datetime.html#strftime-and-strptime-format-codes

 

PowertTools logger문서:

https://docs.powertools.aws.dev/lambda/python/1.28.0/core/logger/