Google Cloud Run Jobs 日志记录将包含多行的异常消息拆分为多个日志条目

Google Cloud Run Jobs logging splits Exception MESSAGES with multiple lines into multiple log entries

提问人:HaroldFinch 提问时间:9/28/2023 更新时间:9/28/2023 访问量:190

问:

几天前,在我公司的一项 Cloud Run 作业中引发了 Python RuntimeError,导致它停止。

不幸的是,Cloud Run 的日志记录以一种糟糕的方式处理了该 RuntimeError。

它正确地将 RuntimeError 的堆栈跟踪中的所有行放在第一个日志条目中。

但是 RuntimeError 的消息(包含多行文本(每行文本都包含重要的诊断信息)被破坏了。该消息的第一行位于包含堆栈跟踪的第一个日志条目中。但是剩下的每一行(空白行除外)都被放入其自己的后续日志条目中。

下面是该作业的“Google Cloud 运行日志”选项卡的屏幕截图,显示了这一点。在第一个日志条目(顶部)中,您可以看到完整的堆栈跟踪以及 RuntimeError 消息的第一行(“Caught some Exception (see cause);正在处理...“) 但在那之后出现了许多日志条目,每个条目都是 RuntimeError 消息中的单个子行。屏幕截图仅包含后续行中的前 4 行,第一行是文本“{'broker_order_id': '196056769652',”。

enter image description here

RuntimeError 消息处理显然是一场灾难:你必须知道后续的行来得更晚(我一开始以为它们根本没有打印),很难读取它们,它们的日志级别不再是 ERROR,而是不存在,等等。

有谁知道是否

  1. 有一种治疗方法
  2. 我们没有正确执行 Cloud Run 日志记录
  3. 这是一个已知的错误,或者我需要向 Google 报告的错误

?


在提交这个问题之前,我做了网络搜索。

我发现很多人报告说,到 2022 年,异常堆栈跟踪正在多行打印:Python、Java、Java

但是这些链接中报告的堆栈跟踪多行/多日志条目问题现在似乎已经解决。我报告的问题是,如果异常的文本消息(而不是堆栈跟踪)有多行。


我的公司在 1 年前>设置了 Cloud Run Jobs 日志记录,当时 Cloud Run Jobs 还处于测试阶段,并且不受 Cloud 日志记录工具的完全支持。

在缩写形式中,我们的 Cloud Run Jobs 日志记录配置类似于如下所示的 Python 代码。

是否有可能此日志记录配置已过期并导致此问题?

LOG_FORMAT: str = (
    "%(asctime)s.%(msecs)03dZ "
    "%(levelname)s "
    "%(name)s.%(funcName)s "
    "#%(lineno)d "
    "- "
    "%(message)s"
)

DATE_FORMAT: str = "%Y-%m-%d %H:%M:%S"

_is_logging_configured: bool = False


def get_logger(name: str) -> Logger:
    config_logging()
    
    return getLogger(name)


def config_logging() -> None:
    if _is_logging_configured:
        return
    
    config_gcp_cloud_run_job_logging()
    
    _is_logging_configured = True


def config_gcp_cloud_run_job_logging() -> None:
    root_logger = getLogger()
    root_logger.setLevel(os.environ.get("LOG_LEVEL", "WARNING"))
    formatter = get_logging_formatter()
    
    # get metadata about the execution environment
    region = retrieve_metadata_server(_REGION_ID)
    project = retrieve_metadata_server(_PROJECT_NAME)
    
    # build a manual resource object
    cr_job_resource = Resource(
        type = "cloud_run_job",
        labels = {
            "job_name": os.environ.get("CLOUD_RUN_JOB", "unknownJobId"),
            "location": region.split("/")[-1] if region else "",
            "project_id": project,
        },
    )
    
    # configure library using CloudLoggingHandler with custom resource
    client = Client()
    
    # use labels to assign logs to execution
    labels = {"run.googleapis.com/execution_name": os.environ.get("CLOUD_RUN_EXECUTION", "unknownExecName")}
    
    handler = CloudLoggingHandler(client, resource = cr_job_resource, labels = labels)
    handler.setFormatter(formatter)
    setup_logging(handler)


def get_logging_formatter() -> Formatter:
    formatter = Formatter(fmt = LOG_FORMAT, datefmt = DATE_FORMAT)
    Formatter.converter = time.gmtime
    return formatter
python 异常 记录 google-cloud-run multiline

评论

0赞 Hemanth Kumar 10/2/2023
让我知道共享的信息是否有帮助。如果您有任何进一步的疑问,我很乐意为您提供帮助。如果答案有帮助,当有人回答我的问题时,我该怎么办?

答:

1赞 Hemanth Kumar 9/28/2023 #1
  • 这是一个已知的错误,已在公共问题跟踪器中报告给 Google Cloud,目前产品工程团队正在研究此问题,没有预计到达时间。这可能是 appserver 日志异常分组器未将此堆栈跟踪分组到单个日志行中的问题。如果需要,可以在该 PIT 链接中添加您的输入或更多详细信息作为注释。不过,如果您觉得需要单独的请求,则可以使用此 PIT 链接提出请求。

  • 为了克服这个问题,您可以使用 Fluent Bit 提供的“多行”过滤器,它有助于连接最初属于一个上下文但被拆分到多个记录或日志行的消息。常见示例是堆栈跟踪或以多行打印日志的应用程序。

  • 根据 Maxim Ponomarev 的这个 SO,以避免日志中有关相同异常的重复消息。最好记录有关 RuntimeException(或任何其他异常)的消息,以便更容易识别异常并避免重复消息。

评论

0赞 HaroldFinch 10/3/2023
感谢您的回复!您链接到的 Google 错误问题似乎在谈论堆栈跟踪被拆分为多行。从我发布的屏幕截图中可以看出,我实际上已根据需要将堆栈跟踪中的所有行合并到单个日志中。问题在于 Exception 的文本消息,它与它的堆栈跟踪不同:我的文本消息也是多行的,第 2 行和后面的行都放入自己的日志条目中,而不是全部成为原始日志的一部分。我希望 Google 错误团队意识到这一点。
0赞 Hemanth Kumar 10/3/2023
@HaroldFinch : 感谢您的回复,如果您觉得现有的 PIT 与您的关注点不同,那么最好使用 PIT LInk 提出新的错误,或者您也可以在现有错误中发表评论,以便 Google 员工可以更准确地了解这个问题。