GCP 上的云功能：没有退出日志答案

【问题标题】：Cloud function on GCP: no exit logGCP 上的云功能：没有退出日志
【发布时间】：2021-11-06 22:15:34
【问题描述】：

我有一个由主题发布订阅触发的谷歌云功能。

大多数时候，一切都像这样运行良好：

2021-11-06 15:12:38.830 GMT vote_stage oga5hymuzx4p Function execution started
2021-11-06 15:13:45.392 GMT vote_stage oga5hymuzx4p Function execution took 66563 ms, finished with status: 'ok'

但不幸的是，二十次，我只能看到这个：

2021-11-06 15:08:45.139 GMT vote_stage rvfnd4wo5nwd Function execution started

没有退出日志怎么可能？

下面是函数的代码：

def vote_stage(event, context):
    assert context == context
    call_datetime = reusable.time.get_now()
    game_id = event['attributes']['game_id']
    logger.info(f'start, game_id={game_id}')
    game = build_game(game_id)
    resp = ut.exceptions.ExceptionsHandler(game).handle_vote_stage_exceptions()
    if resp:
        logger.info(f'exception, game_id={game_id}')
        return resp
    game.dict['vote_stage_last_trigger'] = reusable.time.get_now()
    ut.firestore.FirestoreEditor(game).set_game(merge=True)

    while True:
        game = build_game(game_id)
        ut.slack.SlackOperator(game).update_vote_stage_lower()
        c1 = len(game.frozen_guessers) == 1
        c2 = game.time_left_to_vote <= 0
        c3 = not game.remaining_potential_voters
        if c1 or c2 or c3:
            game.dict['frozen_voters'] = deepcopy(game.dict['voters'])
            game.dict['vote_stage_over'] = True
            ut.firestore.FirestoreEditor(game).set_game(merge=True)
            game.stage_triggerer.trigger_pre_result_stage()
            logger.info(f'pre_result_stage triggered, game_id={game_id}')
            return make_response('', 200)
        if ut.time.datetime1_minus_datetime2(
                reusable.time.get_now(),
                call_datetime) > game.self_trigger_threshold:
            game.stage_triggerer.trigger_vote_stage()
            logger.info(f'vote_stage self-triggered, game_id={game_id}')
            return make_response('', 200)
        time.sleep(game.refresh_interval)

这里，game.self_trigger_threshold = 60s 和 game.refresh_interval = 9s。 vote_stage 函数的超时时间为 540s。

方法 game.stage_triggerer.trigger_pre_result_stage() 向主题“topic_pre_result_stage”发布消息，触发“pre_result_stage”云函数。

方法 game.stage_triggerer.trigger_vote_stage() 向主题“topic_vote_stage”发布消息，触发“vote_stage”云函数。

我找到的唯一内部日志是：

2021-11-06 15:08:49.594 GMT vote_stage rvfnd4wo5nwd 2021-11-06 15:08:49,594 - INFO - start, game_id=20211106_150714&T01LTPERV4Z&C02EKL5PQAX&U01LFAZNKPV&2694551026434.1707796879169.ce017050e1e74e97332c2a04d4b19c08

这是 Legacy Logs Viewer 的屏幕截图（拍摄于 2021-11-07），显示了此函数执行的所有日志（execution_id = rvfnd4wo5nwd）：

这是 Legacy Logs Viewer 的屏幕截图（拍摄于 2021-11-07），显示了 vote_stage 函数的 level = "Errors" 的所有日志：

如您所见，没有一个是从 2021-11-06 开始的。

【问题讨论】：

您在检查完成之前等待了多长时间？你是怎么看日志的？例如，如果函数崩溃了怎么办……我想这会出现在未过滤的日志中，但可能不会出现在过滤的日志中。也许直接查看 Cloud Logging 看看是否可以看到更多内容。
我只是将这些细节添加到问题中。
处理需要多长时间？什么是云功能超时
处理大约需要70s。超时时间为 540 秒。
这听起来像是一次失败。可能是服务内存不足或其他资源不足。更有可能的是，由于某些系统故障，日志刚刚丢失。您能否检查一下您当前的某些执行 ID 是否仍像您描述的那样运行？

标签： google-cloud-platform google-cloud-functions

【解决方案1】：

我没有错误了。我做了以下更改：我将 publisher.publish(**kwargs) 替换为 publisher.publish(**kwargs).result() 该函数用于触发发布订阅主题。

如https://cloud.google.com/functions/docs/troubleshooting 所述：如果您的函数创建异步任务，它还必须显式等待这些任务完成。

【讨论】：

【解决方案2】：

Cloud Functions 缺少日志条目通常不是预期的情况，可能是由于进程在到达将日志转发到 Cloud Monitoring 的阶段之前终止所致。丢失的日志条目通常不是问题，但可能表明一些不平衡的配置。资源过早终止可能是由于用尽了一些限制。您的函数似乎需要大量时间。

vote_stage oga5hymuzx4p Function execution took 66563 ms, 
finished with status: 'ok'

默认超时时间为 1 分钟，并且可以延长至 9 分钟，因为您的函数说它的超时时间为 540 秒。

https://cloud.google.com/functions/docs/concepts/exec#timeout

在您的设置中，该函数的超时时间接近限制，并且它恰好消耗了大部分执行时间。因此，可能不会捕获日志。尝试 Cloud Functions 配置并提供更多资源可能会有所帮助，但这还不够，因为这里不知道根本原因。

我建议的最佳选择是联系Google Cloud Support 以正确检查后台发生的情况并正确了解该功能的流量特征。 GCP 有一个免费试用版供您试用，并且还提供支持。

【讨论】：