AWS SageMaker自定义model_fn日志在CloudWatch中显示不一致问题

摘要 #

• 我在model_fn中添加了自定义logger.debug("### calling modelfn.")语句。
• 这些自定义日志在CloudWatch中时而显示时而不显示（我方未做任何变更）。

详细信息 #

推理代码 #

%%writefile code/inference_code.py

import os
import json
from transformers import BertTokenizer, BertModel

import logging
import sys

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
logger.addHandler(logging.StreamHandler(sys.stdout))
logger.info("Loading file.")


def model_fn(model_dir):
    """
    Load the model for inference
    """
    logger.debug("### calling modelfn.")
    model_path = os.path.join(model_dir, 'model/')

    logger.debug("### begin try catch.")
    try:
        # Load BERT tokenizer from disk.
        tokenizer = BertTokenizer.from_pretrained("bert-base-uncased")

        # Load BERT model from disk.
        model = BertModel.from_pretrained(model_path)
    except Exception as e:
        logger.debug(f"Exception caught: {type(e).__name__} - {e}")
    logger.debug("### end try catch.")
    model_dict = {'model': model, 'tokenizer':tokenizer}
    return model_dict


def predict_fn(input_data, model):
    """
    Apply model to the incoming request
    """
    logger.debug("### calling predict.")
    logger.debug(type(model))
    tokenizer = model['tokenizer']
    bert_model = model['model']
    encoded_input = tokenizer(input_data, return_tensors='pt')
    return bert_model(**encoded_input)


def input_fn(request_body, request_content_type):
    """
    Deserialize and prepare the prediction input
    """
    logger.debug(f"### calling input_fn with {request_body}, {request_content_type}")
    if request_content_type == "application/json":
        request = json.loads(request_body)
    else:
        request = request_body

    return request


def output_fn(prediction, response_content_type):
    """
    Serialize and prepare the prediction output
    """
    logger.debug(f"### calling output_fn {prediction}, {response_content_type}")
    if response_content_type == "application/json":
        response = json.dumps(prediction)
    else:
        response = str(prediction)

    return response

（注：原代码中"bert-base-uncased"缺失闭合引号，已修正）

部署代码 #

from sagemaker.pytorch import PyTorchModel
from sagemaker import get_execution_role
import time

endpoint_name = "bert-base-" + time.strftime("%Y-%m-%d-%H-%M-%S", time.gmtime())

model = PyTorchModel(
    entry_point="inference_code.py",
    model_data=zipped_model_path,
    role=get_execution_role(),
    framework_version="1.5",
    py_version="py3",
)

predictor = model.deploy(
    initial_instance_count=1, instance_type="ml.m5.xlarge", endpoint_name=endpoint_name, 
    env={"PYTHONUNBUFFERED": "1"}
)

核心问题：自定义model_fn中的日志语句存在时而显示时而不显示的情况！

日志显示正常时，能看到### calling modelfn.等debug日志；日志未显示时，这些debug日志完全缺失。

1. 修复日志重复添加Handler的问题
   当前代码每次加载模块都会给logger新增StreamHandler，可能导致日志输出混乱或被覆盖。修改日志初始化逻辑，避免重复添加：

   logger = logging.getLogger(__name__)
   logger.setLevel(logging.DEBUG)
   # 检查是否已有Handler，避免重复添加
   if not logger.handlers:
       logger.addHandler(logging.StreamHandler(sys.stdout))
   

2. 显式设置SageMaker日志级别
   SageMaker默认可能过滤DEBUG级别的日志，在部署代码的env中添加日志级别配置，确保容器不拦截debug日志：

   predictor = model.deploy(
       initial_instance_count=1, instance_type="ml.m5.xlarge", endpoint_name=endpoint_name, 
       env={"PYTHONUNBUFFERED": "1", "SAGEMAKER_LOG_LEVEL": "DEBUG"}
   )
   

3. 验证模型缓存机制
   SageMaker模型服务会缓存已加载的模型，当模型被缓存时model_fn不会重复执行，自然不会输出对应日志。可通过重启端点或修改模型数据触发重新加载，验证是否因缓存导致日志缺失。

4. 修正代码语法错误
   原推理代码中BertTokenizer.from_pretrained的参数缺失闭合引号，会导致模型加载失败触发异常，修复后可避免因代码报错导致的日志异常。

内容的提问来源于stack exchange，提问作者tfcstack