GitHub ActionsでAzure App Serviceへデプロイする際にリトライを繰り返した結果失敗する #Azure #GitHubActions - しもむブログ

しもむブログ

技術メモ。といっても高度なことは書けないので…初心者がハマったところや、ググってもすぐには出てこないようなものを書くつもり。

GitHub ActionsでAzure App Serviceへデプロイする際にリトライを繰り返した結果失敗する #Azure #GitHubActions

Azure App Service GitHub Actions

  • GitHub ActionsでAzure App Serviceへデプロイする際に、長時間かかった後失敗するという現象に遭遇した
    • 2024年2月のできごとだが公開するまで温めすぎた
  • GitHub Actionsでは失敗となっているが、デプロイ先のアプリの動作を見る限りはきちんと反映されている（と、記憶しているがちょっと自信なし）
  • デプロイには azure/webapps-deploy@v2 (https://github.com/Azure/webapps-deploy) を使用している
  • デバックログを出しながら再実行するとZIP Deployのところでリトライを繰り返しているようだ
  • デプロイ失敗を解消すべくリトライしている原因を探っていく

結論

  • App Serivceのデプロイセンターからリトライの原因となるデプロイのログを削除することで解消した
  • なぜそのようなデプロイが発生したかは不明のままである

調査から解消まで

デバッグログを読む

  • デバッグログを見ると、最後の4行が繰り返し出力されているという状態だった
  • https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z （ローカル時間だと19:50）の結果、ステータスがDeployment status: 0 'Building and Deploying '840447bd-8c31-4bbc-80ca-b1eeb2b366e6'.'. なのでリトライしているようだ
2024-02-13T10:49:50.9061465Z ##***debug***Deployment Step Started
2024-02-13T10:49:50.9064435Z ##***debug***warming up Kudu Service
2024-02-13T10:49:50.9070097Z ##***debug***GET*** https://app-***.scm.azurewebsites.net/api/settings
2024-02-13T10:49:53.7126777Z ##***debug***loaded affinity cookie ***"ARRAffinity=***;Path=/;HttpOnly;Secure;Domain=app-***.scm.azurewebsites.net","ARRAffinitySameSite=***;Path=/;HttpOnly;SameSite=None;Secure;Domain=app-***.scm.azurewebsites.net"***
2024-02-13T10:49:53.7156202Z ##***debug***getAppSettings. Data: ***"statusCode":200,"statusMessage":"OK","headers":***"content-length":"1821","connection":"close","content-type":"application/json; charset=utf-8","date":"Tue, 13 Feb 2024 10:49:52 GMT","server":"Kestrel","set-cookie":***"ARRAffinity=***;Path=/;HttpOnly;Secure;Domain=app-***.scm.azurewebsites.net","ARRAffinitySameSite=***;Path=/;HttpOnly;SameSite=None;Secure;Domain=app-***.scm.azurewebsites.net"***"body":***"deployment_branch":"master","SCM_TRACE_LEVEL":"Verbose","SCM_COMMAND_IDLE_TIMEOUT":"60","SCM_LOGSTREAM_TIMEOUT":"7200"(環境変数など省略)***
2024-02-13T10:49:53.7174534Z ##***debug***warmed up Kudu Service
2024-02-13T10:49:53.7176568Z ##***debug***Archiving . to /home/runner/work/_temp/temp_web_package_029714350853972116.zip
2024-02-13T10:49:58.0118575Z ##***debug***Successfully created archive /home/runner/work/_temp/temp_web_package_029714350853972116.zip
2024-02-13T10:49:58.0129420Z ##***debug***Compressed folder into zip /home/runner/work/_temp/temp_web_package_029714350853972116.zip
2024-02-13T10:49:58.0132992Z ##***debug***Initiated deployment via kudu service for webapp package : /home/runner/work/_temp/temp_web_package_029714350853972116.zip
2024-02-13T10:49:58.0143223Z Package deployment using ZIP Deploy initiated.
2024-02-13T10:49:58.0158673Z ##***debug***setting affinity cookie ***"ARRAffinity=***;Path=/;HttpOnly;Secure;Domain=app-***.scm.azurewebsites.net","ARRAffinitySameSite=***;Path=/;HttpOnly;SameSite=None;Secure;Domain=app-***.scm.azurewebsites.net"***
2024-02-13T10:49:58.0171861Z ##***debug***POST*** https://app-***.scm.azurewebsites.net/api/zipdeploy?isAsync=true&deployer=GITHUB_ZIP_DEPLOY&message=***%22type%22%3A%22deployment%22%2C%22sha%22%3A%22e9039f426f71c2863e8d4c31e9be522cf88c4f99%22%2C%22repoName%22%3A%22***%2F***%22%2C%22actor%22%3A%22***%22%2C%22slotName%22%3A%22production%22%2C%22commitMessage%22%3A%22Merge%20branch%22***
2024-02-13T10:50:05.3723737Z ##***debug***ZIP Deploy response: ***"statusCode":202,"statusMessage":"Accepted","headers":***"content-length":"0","connection":"close","date":"Tue, 13 Feb 2024 10:50:04 GMT","server":"Kestrel","location":"https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z","scm-deployment-id":"639442d9-b51f-46bf-9b56-23a93e3e6cfe","retryafter":"30"***"body":""***
2024-02-13T10:50:05.3730313Z ##***debug***Polling for ZIP Deploy URL: https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z
2024-02-13T10:50:05.3736690Z ##***debug***setting affinity cookie ***"ARRAffinity=***;Path=/;HttpOnly;Secure;Domain=app-***.scm.azurewebsites.net","ARRAffinitySameSite=***;Path=/;HttpOnly;SameSite=None;Secure;Domain=app-***.scm.azurewebsites.net"***
2024-02-13T10:50:05.3742157Z ##***debug***GET*** https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z
2024-02-13T10:50:07.1168652Z ##***debug***POLL URL RESULT: ***"statusCode":202,"statusMessage":"Accepted","headers":***"content-length":"508","connection":"close","content-type":"application/json; charset=utf-8","date":"Tue, 13 Feb 2024 10:50:06 GMT","server":"Kestrel","location":"https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z"***"body":***"id":"temp-be08ac01","status":0,"status_text":"Receiving changes.","author_email":"N/A","author":"N/A","deployer":"GITHUB_ZIP_DEPLOY","message":"Deploying from pushed zip file","progress":"Fetching changes.","received_time":"2024-02-13T10:50:05.1034201Z","start_time":"2024-02-13T10:50:05.1034201Z","end_time":null,"last_success_end_time":null,"complete":false,"active":false,"is_temp":true,"is_readonly":false,"url":null,"log_url":null,"site_name":"app-***","build_summary":***"errors":***,"warnings":***
2024-02-13T10:50:07.1184964Z ##***debug***Deployment status: 0 'Receiving changes.'. retry after 5 seconds
2024-02-13T10:50:12.1223254Z ##***debug***setting affinity cookie ***"ARRAffinity=***;Path=/;HttpOnly;Secure;Domain=app-***.scm.azurewebsites.net","ARRAffinitySameSite=***;Path=/;HttpOnly;SameSite=None;Secure;Domain=app-***.scm.azurewebsites.net"***
2024-02-13T10:50:12.1228871Z ##***debug***GET*** https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z
2024-02-13T10:50:15.1075159Z ##***debug***POLL URL RESULT: ***"statusCode":202,"statusMessage":"Accepted","headers":***"content-length":"508","connection":"close","content-type":"application/json; charset=utf-8","date":"Tue, 13 Feb 2024 10:50:14 GMT","server":"Kestrel","location":"https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z"***"body":***"id":"temp-be08ac01","status":0,"status_text":"Receiving changes.","author_email":"N/A","author":"N/A","deployer":"GITHUB_ZIP_DEPLOY","message":"Deploying from pushed zip file","progress":"Fetching changes.","received_time":"2024-02-13T10:50:05.1034201Z","start_time":"2024-02-13T10:50:05.1034201Z","end_time":null,"last_success_end_time":null,"complete":false,"active":false,"is_temp":true,"is_readonly":false,"url":null,"log_url":null,"site_name":"app-***","build_summary":***"errors":***,"warnings":***
2024-02-13T10:50:15.1091684Z ##***debug***Deployment status: 0 'Receiving changes.'. retry after 5 seconds
2024-02-13T10:50:20.1125997Z ##***debug***setting affinity cookie ***"ARRAffinity=***;Path=/;HttpOnly;Secure;Domain=app-***.scm.azurewebsites.net","ARRAffinitySameSite=***;Path=/;HttpOnly;SameSite=None;Secure;Domain=app-***.scm.azurewebsites.net"***
2024-02-13T10:50:20.1136295Z ##***debug***GET*** https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z
2024-02-13T10:50:23.7039407Z ##***debug***POLL URL RESULT: ***"statusCode":202,"statusMessage":"Accepted","headers":***"content-length":"791","connection":"close","content-type":"application/json; charset=utf-8","date":"Tue, 13 Feb 2024 10:50:22 GMT","server":"Kestrel","location":"https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z"***"body":***"id":"639442d9-b51f-46bf-9b56-23a93e3e6cfe","status":0,"status_text":"Building and Deploying '639442d9-b51f-46bf-9b56-23a93e3e6cfe'.","author_email":"N/A","author":"N/A","deployer":"GITHUB_ZIP_DEPLOY","message":"***\"type\":\"deployment\",\"sha\":\"e9039f426f71c2863e8d4c31e9be522cf88c4f99\",\"repoName\":\"***/***\",\"actor\":\"***\",\"slotName\":\"production\",\"commitMessage\":\"Merge branch\"***","progress":"Running deployment command...","received_time":"2024-02-13T10:50:15.5382064Z","start_time":"2024-02-13T10:50:17.0537542Z","end_time":null,"last_success_end_time":null,"complete":false,"active":false,"is_temp":false,"is_readonly":true,"url":null,"log_url":null,"site_name":"app-***","build_summary":***"errors":***,"warnings":***
2024-02-13T10:50:23.7062096Z ##***debug***Deployment status: 0 'Building and Deploying '639442d9-b51f-46bf-9b56-23a93e3e6cfe'.'. retry after 5 seconds
2024-02-13T10:50:28.7075619Z ##***debug***setting affinity cookie ***"ARRAffinity=***;Path=/;HttpOnly;Secure;Domain=app-***.scm.azurewebsites.net","ARRAffinitySameSite=***;Path=/;HttpOnly;SameSite=None;Secure;Domain=app-***.scm.azurewebsites.net"***
2024-02-13T10:50:28.7080985Z ##***debug***GET*** https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z
2024-02-13T10:50:32.6722500Z ##***debug***POLL URL RESULT: ***"statusCode":202,"statusMessage":"Accepted","headers":***"content-length":"791","connection":"close","content-type":"application/json; charset=utf-8","date":"Tue, 13 Feb 2024 10:50:31 GMT","server":"Kestrel","location":"https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z"***"body":***"id":"639442d9-b51f-46bf-9b56-23a93e3e6cfe","status":0,"status_text":"Building and Deploying '639442d9-b51f-46bf-9b56-23a93e3e6cfe'.","author_email":"N/A","author":"N/A","deployer":"GITHUB_ZIP_DEPLOY","message":"***\"type\":\"deployment\",\"sha\":\"e9039f426f71c2863e8d4c31e9be522cf88c4f99\",\"repoName\":\"***/***\",\"actor\":\"***\",\"slotName\":\"production\",\"commitMessage\":\"Merge branch\"***","progress":"Running deployment command...","received_time":"2024-02-13T10:50:15.5382064Z","start_time":"2024-02-13T10:50:17.0537542Z","end_time":null,"last_success_end_time":null,"complete":false,"active":false,"is_temp":false,"is_readonly":true,"url":null,"log_url":null,"site_name":"app-***","build_summary":***"errors":***,"warnings":***
2024-02-13T10:50:32.6741540Z ##***debug***Deployment status: 0 'Building and Deploying '639442d9-b51f-46bf-9b56-23a93e3e6cfe'.'. retry after 5 seconds
2024-02-13T10:50:37.6759823Z ##***debug***setting affinity cookie ***"ARRAffinity=***;Path=/;HttpOnly;Secure;Domain=app-***.scm.azurewebsites.net","ARRAffinitySameSite=***;Path=/;HttpOnly;SameSite=None;Secure;Domain=app-***.scm.azurewebsites.net"***
2024-02-13T10:50:37.6765858Z ##***debug***GET*** https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z
2024-02-13T10:50:40.5658521Z ##***debug***POLL URL RESULT: ***"statusCode":202,"statusMessage":"Accepted","headers":***"content-length":"791","connection":"close","content-type":"application/json; charset=utf-8","date":"Tue, 13 Feb 2024 10:50:39 GMT","server":"Kestrel","location":"https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z"***"body":***"id":"639442d9-b51f-46bf-9b56-23a93e3e6cfe","status":0,"status_text":"Building and Deploying '639442d9-b51f-46bf-9b56-23a93e3e6cfe'.","author_email":"N/A","author":"N/A","deployer":"GITHUB_ZIP_DEPLOY","message":"***\"type\":\"deployment\",\"sha\":\"e9039f426f71c2863e8d4c31e9be522cf88c4f99\",\"repoName\":\"***/***\",\"actor\":\"***\",\"slotName\":\"production\",\"commitMessage\":\"Merge branch\"***","progress":"Running deployment command...","received_time":"2024-02-13T10:50:15.5382064Z","start_time":"2024-02-13T10:50:17.0537542Z","end_time":null,"last_success_end_time":null,"complete":false,"active":false,"is_temp":false,"is_readonly":true,"url":null,"log_url":null,"site_name":"app-***","build_summary":***"errors":***,"warnings":***
2024-02-13T10:50:40.5671403Z ##***debug***Deployment status: 0 'Building and Deploying '639442d9-b51f-46bf-9b56-23a93e3e6cfe'.'. retry after 5 seconds
2024-02-13T10:50:45.5701532Z ##***debug***setting affinity cookie ***"ARRAffinity=***;Path=/;HttpOnly;Secure;Domain=app-***.scm.azurewebsites.net","ARRAffinitySameSite=***;Path=/;HttpOnly;SameSite=None;Secure;Domain=app-***.scm.azurewebsites.net"***
2024-02-13T10:51:02.3336114Z ##***debug***setting affinity cookie ***"ARRAffinity=***;Path=/;HttpOnly;Secure;Domain=app-***.scm.azurewebsites.net","ARRAffinitySameSite=***;Path=/;HttpOnly;SameSite=None;Secure;Domain=app-***.scm.azurewebsites.net"***
2024-02-13T10:51:02.3345571Z ##***debug***GET*** https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z
2024-02-13T10:51:06.1413954Z ##***debug***POLL URL RESULT: ***"statusCode":202,"statusMessage":"Accepted","headers":***"content-length":"747","connection":"close","content-type":"application/json; charset=utf-8","date":"Tue, 13 Feb 2024 10:51:05 GMT","server":"Kestrel","location":"https://app-***.scm.azurewebsites.net:443/api/deployments/latest?deployer=GITHUB_ZIP_DEPLOY&time=2024-02-13_10-50-05Z"***"body":***"id":"840447bd-8c31-4bbc-80ca-b1eeb2b366e6","status":0,"status_text":"Building and Deploying '840447bd-8c31-4bbc-80ca-b1eeb2b366e6'.","author_email":"N/A","author":"N/A","deployer":"GITHUB_ZIP_DEPLOY","message":"***\"type\":\"deployment\",\"sha\":\"b711641acd9bf6d9b98fe2ff00be0b648c1a41b0\",\"repoName\":\"***/***\",\"actor\":\"***\",\"slotName\":\"production\",\"commitMessage\":\"\"***","progress":"Running deployment command...","received_time":"2024-02-08T05:45:12.914337Z","start_time":"2024-02-08T05:45:15.8336118Z","end_time":null,"last_success_end_time":null,"complete":false,"active":false,"is_temp":false,"is_readonly":true,"url":null,"log_url":null,"site_name":"app-***","build_summary":***"errors":***,"warnings":***
2024-02-13T10:51:06.1426199Z ##***debug***Deployment status: 0 'Building and Deploying '840447bd-8c31-4bbc-80ca-b1eeb2b366e6'.'. retry after 5 seconds
（以降、4行繰り返し）

同じ現象を探してみる

  • ログのメッセージ等でググってみると、Function Appではあるが同様の現象が議論されていた

github.com

  • デプロイセンターを確認してみて、原因となっているログを削除すれば解決しそうである

App Serivceのデプロイセンターでログを確認する

  • 840447b の状態はRunning deployment com... であった
  • 他のデプロイの成功とも異なるし、GitHub Actionsのログとも内容的には一致しているようだ

ログの詳細

  • ログの詳細を見ると、Running deployment command... で終わっている

  • 成功時はこちら

ログを表示する

  • 「ログを表示する...」をクリックしてみる。成功時のログと比べてみてもたしかに正常終了していない
Command: "/home/site/deployments/tools/deploy.sh"
Handling Basic Web Site deployment.
Kudu sync from: '/tmp/zipdeploy/extracted' to: '/home/site/wwwroot'
Copying file: '***.dll'
Copying file: （中略）
Omitting next output lines...
/home/site/deployments/tools/deploy.sh: line 82:   886 Killed                  "$KUDU_SYNC_CMD" -v 50 $IGNORE_MANIFEST_PARAM -f "$DEPLOYMENT_SOURCE" -t "$DEPLOYMENT_TARGET" -n "$NEXT_MANIFEST_PATH" -p "$PREVIOUS_MANIFEST_PATH" -i ".git;.hg;.deployment;deploy.sh"
/home/site/deployments/tools/deploy.sh: line 82:   886 Killed                  "$KUDU_SYNC_CMD" -v 50 $IGNORE_MANIFEST_PARAM -f "$DEPLOYMENT_SOURCE" -t "$DEPLOYMENT_TARGET" -n "$NEXT_MANIFEST_PATH" -p "$PREVIOUS_MANIFEST_PATH" -i ".git;.hg;.deployment;deploy.sh"\n/opt/Kudu/Scripts/starter.sh "/home/site/deployments/tools/deploy.sh"
  • 成功時のログはこちら
Command: "/home/site/deployments/tools/deploy.sh"
Handling Basic Web Site deployment.
Kudu sync from: '/tmp/zipdeploy/extracted' to: '/home/site/wwwroot'
Copying file: '***.dll'
Copying file: （中略）
Omitting next output lines...
Processed *** files...
Finished successfully.

ログを削除する

  • デプロイセンターから正常終了していないログを選択して削除する

  • 削除ロックがかかっていたので失敗

  • 削除ロックを削除してリトライ、正常に削除できた（ちゃんと削除ロックを戻しておく）

  • Github Actionsを実行して無事デプロイが成功することを確認した