Cloud Workflowsのコールロギング機能を試してみる

先日GAになったWorkflowsのロギング機能を試してみた

Release notes | Workflows | Google Cloud

Send logs to Cloud Logging | Workflows | Google Cloud

実行時にオプションを付けることでステップ名、関数名、関数引数、呼び出しレスポンスなどをCloud Loggingに流すことができる

今までは特定の箇所でsys.logを実行してログに流して状況を確認する必要があったがその必要がなくなった

とりあえず試してみる

使い方

--call-log-levelでLoggingに流すログの粒度を指定できる

今回は--call-log-level=log-all-callsをつけてすべてのステップのログを見てみる

gcloud workflows run --call-log-level=log-all-calls xxxxx

以前色々試したワークフローがあるのでいくつか実行してみる

コネクタ

BigQueryコネクタを使っているサンプル

workflow.yml

- get_formatted_string:
    call: googleapis.bigquery.v2.jobs.query
    args:
      projectId: ${sys.get_env("GOOGLE_CLOUD_PROJECT_ID")}
      body:
        query: "SELECT FORMAT_DATE('%Y%m%d', DATE_SUB(CURRENT_DATE('Asia/Tokyo'), INTERVAL 1 DAY)),FORMAT_DATE('%Y%m%d', DATE_SUB(CURRENT_DATE('Asia/Tokyo'), INTERVAL 8 DAY))"
        useLegacySql: false
    result: query_result

- log_result:
    call: sys.log
    args:
      text: ${query_result}
      severity: INFO

- return_value:
    return: ${query_result}

結果

Waiting for execution [3b6985dc-c7ee-42ea-a8b2-cb9a6bb9dacf] to complete...done.
argument: 'null'
callLogLevel: LOG_ALL_CALLS
.....
result: '{"cacheHit":false,"jobComplete":true,"jobReference":{"jobId":"job_2f3ZUQ4d49N1Qg_gTa4FxE9AP8UY","location":"US","projectId":"terraform-sample-294414"},"kind":"bigquery#queryResponse","rows":[{"f":[{"v":"20220427"},{"v":"20220420"}]}],"schema":{"fields":[{"mode":"NULLABLE","name":"f0_","type":"STRING"},{"mode":"NULLABLE","name":"f1_","type":"STRING"}]},"totalBytesProcessed":"0","totalRows":"1"}'
startTime: '2022-04-27T18:59:23.679260559Z'
state: SUCCEEDED

実行ログから遷移して内容を見る

Logging上でのログタイプは

@type: type.googleapis.com/google.cloud.workflows.type.EngineCallLog

1つの呼び出しで呼び出し時のログ、結果のログの2種類が出力される

どちらもstateやstepでどこからの呼び出しでどのような状態なのかというのが分かる

呼び出し時のログではBigQueryのAPIへ投げているリクエストの内容が分かる

結果のログでは実際に帰ってきたレスポンスのJSONの内容が分かる（画像だと見切れてしまっているが）

また、ログ出力のstepもログに記録される

画像ではsys.log呼び出し時、実際にsys.logで流したログ、sys.log呼び出し結果のログの順で並んでいる

サブワークフロー

workflow.yml

main:
  steps:
    - call_subworkflow1:
        call: sum
        args:
          n1: 1
          n2: 1
        result: total1

    - call_subworkflow2:
        call: sum
        args:
          n1: 2
          n2: 2
        result: total2


    - return_value:
        return: ${total1 + total2}

sum:
  params: [n1, n2]
  steps:
    - return_value:
        return: ${n1 + n2}

結果

call_subworkflow1の呼び出し時の情報
call_subworkflow1の結果
call_subworkflow2の呼び出し時の情報
call_subworkflow2の結果

と言った感じで記録される

ドキュメントの通りで、workflow内での計算などはログには出力されない

http呼び出し、例外ハンドリング

例外をハンドリングしている場合

request2はわざとリクエストが失敗するように設定している

workflow.yml

main:
  steps:
    - multi_request:
        try:
          steps:
            - request1:
                call: http.get
                args:
                  url: https://jsonplaceholder.typicode.com/todos/1
                result: response1
            - request2:
                call: http.get
                args:
                  url: https://jsonplaceholder.typicode.com/todos/aa
                result: response2
            - return_value:
                return: ${response2}

        except:
          as: e
          steps:
            - log_error:
                call: sys.log
                args:
                  text: ${json.encode_to_string(e)}
                  severity: CRITICAL
            - raise_error:
                raise: ${e}

結果

argument: 'null'
callLogLevel: LOG_ALL_CALLS
endTime: '2022-04-27T19:21:45.260804221Z'
error:
  context: |-
    HTTP server responded with error code 404
    in step "raise_error", routine "main", line: 28
  payload: '{"body":{},"code":404,"headers":{"Access-Control-Allow-Credentials":"true","Alt-Svc":"h3=\":443\";
    ma=86400, h3-29=\":443\"; ma=86400","Cache-Control":"max-age=43200","Cf-Cache-Status":"MISS","Cf-Ray":"7029ec479aff298c-ORD","Connection":"keep-alive","Content-Length":"2","Content-Type":"application/json;
    charset=utf-8","Date":"Wed, 27 Apr 2022 19:21:44 GMT","Etag":"W/\"2-vyGp6PvFo4RvsFtPoIWeCReyIC8\"","Expect-Ct":"max-age=604800,
    report-uri=\"https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct\"","Expires":"-1","Nel":"{\"success_fraction\":0,\"report_to\":\"cf-nel\",\"max_age\":604800}","Pragma":"no-cache","Report-To":"{\"endpoints\":[{\"url\":\"https:\\/\\/a.nel.cloudflare.com\\/report\\/v3?s=CEYO%2F644%2Ffwt4iiGxBPNj4m3nYIP9lS8Fitaq48M56x4PzpcVD0%2B%2BYym8XJQnzEraGK37yQFllshrn5eGo0v5I%2F1yRvjOBzqIw1%2Fql2HCXIiJtmMh21spSPbpxIQsgpToxeIUf%2FCstrvw9fxZnJE\"}],\"group\":\"cf-nel\",\"max_age\":604800}","Server":"cloudflare","Vary":"Origin,
    Accept-Encoding","Via":"1.1 vegur","X-Content-Type-Options":"nosniff","X-Powered-By":"Express","X-Ratelimit-Limit":"1000","X-Ratelimit-Remaining":"999","X-Ratelimit-Reset":"1651087346"},"message":"HTTP
    server responded with error code 404","tags":["HttpError"]}'
  stackTrace:
    elements:
    - position:
        column: '17'
        length: '5'
        line: '28'
      routine: main
      step: raise_error
.....
startTime: '2022-04-27T19:21:44.608344355Z'
state: FAILED