はじめに

以下の記事の続きとなります。

この記事ではリモートビルドではなく、ローカルビルドデプロイを利用した場合の挙動を確認します。

TL;DR

ローカルビルド+zipデプロイによるリリースを行う場合は、Python仮想環境は、.venv ではなく、antenv という名称でつくりリリースモジュールに含める必要がある
djangoならzipモジュール作成前に　manage.py collectstatic も実施しておく必要がある。
すなわち Oryxがビルド時にやっていることを事前に実施しておく必要がある。

ローカルビルドとは

Kudu 上での Oryx によるビルドを行わず、事前に必要なパッケージすべてを含めたモジュールをリリースする方法となります。
例えば GitHub Actions を構成した場合、以下の yaml に見られるように、GitHub Actions の実行環境上で pip install が行われています。

リリースモジュールの準備

以下のコマンドで作成します。
VSCodeによって作成された .deployment ファイルを含めないようにします。含めてしまうとその内容に従ってリモートビルドが実行されてしまいます。
一方で zip ファイルには .venvディレクトリも含まれるようにします。

zip -r ../zipDeployRelease.zip . --exclude "./.git/*" "./.vscode/*" ".devcontainer/*" ".github/*" ".deployment"

zipデプロイの実行

パラメーターは以下のとおりです。
?clean=true&restart=true&isAsync=true"

curl -u "$basicAuthInfo"  -X POST -T ./zipDeployRelease.zip "https://python-remote-build.scm.azurewebsites.net/api/zipdeploy?clean=true&restart=true&isAsync=true" -v

※ここでは /api/publish?type=zip ではなく、/api/zipdeploy を用いています。/api/publishだとisAsync が効かなかった。

Kudu上での処理内容

Oryx ビルドが行われないとき
POSTに対する応答は 202 でリモートビルド有効時と変わりはありません。

POST_api-zipdeploy_202_1s.xml

POST_api-zipdeploy_202_1s.xml

<step title="Incoming Request" date="2023-11-25T07:29:19.749" instance="157a08" url="/api/zipdeploy?clean=true&amp;restart=true&amp;isAsync=true" method="POST" type="request" pid="87,1,20" Accept="*/*" Host="python-remote-build.scm.azurewebsites.net" User-Agent="curl/7.81.0" Authorization="Bas..." Expect="100-continue" Content-Length="36981196" X-ARR-LOG-ID="5210868f-186a-41bd-b563-a7436d9f32f1" CLIENT-IP=[マスク]:63274" X-Client-IP="[マスク]" X-SITE-DEPLOYMENT-ID="python-remote-build" WAS-DEFAULT-HOSTNAME="python-remote-build.scm.azurewebsites.net" X-Forwarded-Proto="https" X-AppService-Proto="https" X-Forwarded-TlsVersion="1.2" X-WAWS-Unencoded-URL="/api/zipdeploy?clean=true&amp;restart=true&amp;isAsync=true" X-Client-Port="63274" >
  <step title="Cleanup Xml Logs" date="2023-11-25T07:29:19.755" /><!-- duration: 14ms -->
  <step title="ZipPushDeploy" date="2023-11-25T07:29:19.783" >
    <step title="ZipDeploy. Extract zip." date="2023-11-25T07:29:19.810" /><!-- duration: 5ms -->
    <step title="Writing artifact to /tmp/zipdeploy/aaf828e3-2bf3-4bf6-90c8-22a702e6590d.zip" date="2023-11-25T07:29:19.848" /><!-- duration: 891ms -->
    <step title="Start deployment in the background" date="2023-11-25T07:29:20.755" >
      <step title="Acquiring Deployment Lock" date="2023-11-25T07:29:20.784" /><!-- duration: 9ms -->
      <step title="Acquired Deployment Lock" date="2023-11-25T07:29:20.827" /><!-- duration: 4ms -->
    </step><!-- duration: 166ms -->
  </step><!-- duration: 1147ms -->
  <step title="Outgoing response" date="2023-11-25T07:29:20.935" type="response" statusCode="202" statusText="Accepted" /><!-- duration: 5ms -->
</step><!-- duration: 1196ms -->

一方で、実際のバックグラウンド処理は Oryx 実行時と異なります。

Basic Builder が用いられ、KuduSyncによるファイルコピーが行われます。これは Node.js 環境でローカルビルドを用いた場合と同様の動作となります。
ファイルコピーが行われるため遅いです。この例では 656486ms かかっています。

Background_POST_api-zipdeploy_pending.xml

Background_POST_api-zipdeploy_pending.xml

<step title="BackgroundTrace" date="2023-11-25T07:29:20.767" instance="157a08" url="/api/zipdeploy" method="POST" >
  <step title="Creating temporary deployment - FetchDeploymentManager" date="2023-11-25T07:29:20.836" /><!-- duration: 5ms -->
  <step title="Creating temporary deployment" date="2023-11-25T07:29:20.846" /><!-- duration: 69ms -->
  <step title="Performing fetch based deployment" date="2023-11-25T07:29:20.983" >
    <step title="Cleaning up temp folders from previous zip deployments and extracting pushed zip file /tmp/zipdeploy/aaf828e3-2bf3-4bf6-90c8-22a702e6590d.zip (35.27 MB) to /tmp/zipdeploy/extracted" date="2023-11-25T07:29:22.147" >
      <step title="ChmodRecursive Process exited with total time taken in ms: 803" date="2023-11-25T07:29:38.532" /><!-- duration: 12ms -->
    </step><!-- duration: 16404ms -->
    <step title="Before sending BuildRequestReceived status to /api/updatedeploystatus" date="2023-11-25T07:29:40.573" /><!-- duration: 9ms -->
    <step title=" PostAsync - Trying to send BuildRequestReceived deployment status to /api/app/updatedeploystatus. DeploymentId is 5b189bc6-2956-45f7-b7fc-bb54862f4de6" date="2023-11-25T07:29:40.587" /><!-- duration: 5ms -->
    <step title=" PostAsync - Trying to send BuildInProgress deployment status to /api/app/updatedeploystatus. DeploymentId is 5b189bc6-2956-45f7-b7fc-bb54862f4de6" date="2023-11-25T07:29:41.305" /><!-- duration: 13ms -->
    <step title="Deployment timer started" date="2023-11-25T07:29:41.474" >
      <step title="DeploymentManager.Deploy(id:5b189bc6-2956-45f7-b7fc-bb54862f4de6)" date="2023-11-25T07:29:41.480" >
        <step title="Collecting changeset information" date="2023-11-25T07:29:41.499" /><!-- duration: 114ms -->
        <step title="Updating submodules" date="2023-11-25T07:29:41.629" /><!-- duration: 1136ms -->
        <step title="Determining deployment builder" date="2023-11-25T07:29:43.010" >
          <step title="Builder is BasicBuilder" date="2023-11-25T07:29:43.032" /><!-- duration: 5ms -->
        </step><!-- duration: 32ms -->
        <step title="PreDeployment: context.CleanOutputPath False" date="2023-11-25T07:29:43.104" >
          <step title="PreDeployment: context.OutputPath /home/site/wwwroot" date="2023-11-25T07:29:43.240" >
            <step title="Building" date="2023-11-25T07:29:43.382" >
              <step title="Generating deployment script" date="2023-11-25T07:29:43.493" >
                <step title="Using cached version of the deployment script for command: -y --no-dot-deployment -r &quot;/tmp/zipdeploy/extracted&quot; -o &quot;/home/site/deployments/tools&quot; --basic --sitePath &quot;/tmp/zipdeploy/extracted&quot;" date="2023-11-25T07:29:43.566" /><!-- duration: 4ms -->
              </step><!-- duration: 104ms -->
              <step title="Executing external process" date="2023-11-25T07:29:43.800" type="process" path="starter.sh" arguments="&quot;/home/site/deployments/tools/deploy.sh&quot;" /><!-- duration: 654220ms -->
              <step title="Triggering recycle (preview mode disabled)." date="2023-11-25T07:40:38.321" /><!-- duration: 5ms -->
              <step title="Modified file to trigger a restart of the app container." date="2023-11-25T07:40:38.364" /><!-- duration: 22ms -->
              <step title="Skip function trigger and logicapp sync because function is not enabled." date="2023-11-25T07:40:38.391" /><!-- duration: 8ms -->
            </step><!-- duration: 656486ms -->
          </step><!-- duration: 656643ms -->
          <step title="Cleaning up temp files" date="2023-11-25T07:40:39.887" /><!-- duration: 14ms -->
          <step title="Cleaning up temp files" date="2023-11-25T07:40:39.911" /><!-- duration: 508ms -->
          <step title="Reloading status file with latest updates" date="2023-11-25T07:40:40.450" >
            <step title="WebHooksManager.PublishEventAsync: PostDeployment" date="2023-11-25T07:40:40.455" /><!-- duration: 34ms -->
          </step><!-- duration: 42ms -->
          <step title=" PostAsync - Trying to send BuildSuccessful deployment status to /api/app/updatedeploystatus. DeploymentId is 5b189bc6-2956-45f7-b7fc-bb54862f4de6" date="2023-11-25T07:40:40.502" /><!-- duration: 6ms -->
          <step title="Begin HttpPost https://python-remote-build.scm.azurewebsites.net/api/app/updatedeploystatus, x-ms-request-id: 00000000-0000-0000-0000-000000000000" date="2023-11-25T07:40:40.584" /><!-- duration: 5ms -->
          <step title="End HttpPost, status: OK" date="2023-11-25T07:40:41.166" /><!-- duration: 10ms -->
          <step title="Cleaning up temporary deployment - fetch deployment was successful" date="2023-11-25T07:40:41.180" /><!-- duration: 4ms -->
        </step><!-- duration: 658333ms -->
      </step><!-- duration: 660015ms -->
kudu_ssh_user@38efc0f856f9:~/LogFiles/kudu/trace$

処理の詳細は、/home/site/deployments//log.log に残されています。

log.log

2023-11-25T07:29:41.7484708Z,Updating submodules.,5d98371b-6447-413a-8ed7-81d3de86b85c,0
2023-11-25T07:29:42.8847728Z,Preparing deployment for commit id '5b189bc6-2'.,051567f3-e97e-4e7b-b19a-a6a04d675884,0
2023-11-25T07:29:43.2311075Z,PreDeployment: context.CleanOutputPath False,8a209a56-dc8c-4cd1-98de-98ba2d27d9c4,0
2023-11-25T07:29:43.3617760Z,PreDeployment: context.OutputPath /home/site/wwwroot,15a06107-607e-460c-a50a-026c9b2cbb02,0
2023-11-25T07:29:43.4839743Z,Generating deployment script.,ef0b9fbd-f0fe-4544-84aa-78f334adad1c,0
	2023-11-25T07:29:43.5762295Z,Using cached version of deployment script (command: 'azure -y --no-dot-deployment -r "/tmp/zipdeploy/extracted" -o "/home/site/deployments/tools" --basic --sitePath "/tmp/zipdeploy/extracted"').,,0
2023-11-25T07:29:43.7230121Z,Running deployment command...,3c0c6d39-0f72-4fa0-83bb-3d754475d808,0
	2023-11-25T07:29:43.7320186Z,Command: "/home/site/deployments/tools/deploy.sh",,0
	2023-11-25T07:29:43.9139396Z,Handling Basic Web Site deployment.,,0
	2023-11-25T07:29:44.3188463Z,Kudu sync from: '/tmp/zipdeploy/extracted' to: '/home/site/wwwroot',,0
	2023-11-25T07:29:44.5148023Z,Copying file: '.env.sample',,0
	2023-11-25T07:29:44.5345344Z,Copying file: '.gitattributes',,0
	2023-11-25T07:29:44.5752252Z,Copying file: '.gitignore',,0
	2023-11-25T07:29:44.6029320Z,Copying file: 'CHANGELOG.md',,0
	2023-11-25T07:29:44.6255827Z,Copying file: 'CONTRIBUTING.md',,0
	2023-11-25T07:29:44.7335738Z,Copying file: 'LICENSE.md',,0
	2023-11-25T07:29:44.7498825Z,Copying file: 'README.md',,0
	2023-11-25T07:29:44.7709123Z,Copying file: 'db.sqlite3',,0
	2023-11-25T07:29:44.8035789Z,Copying file: 'manage.py',,0
	2023-11-25T07:29:44.8240534Z,Copying file: 'requirements.txt',,0
	2023-11-25T07:29:44.8666658Z,Copying file: '.venv/pyvenv.cfg',,0
	2023-11-25T07:29:44.9608116Z,Copying file: '.venv/bin/Activate.ps1',,0
	2023-11-25T07:29:44.9949745Z,Copying file: '.venv/bin/activate',,0
	2023-11-25T07:29:45.0110061Z,Copying file: '.venv/bin/activate.csh',,0
	2023-11-25T07:29:45.0386798Z,Copying file: '.venv/bin/activate.fish',,0
	2023-11-25T07:29:45.0727696Z,Copying file: '.venv/bin/django-admin',,0
	2023-11-25T07:29:45.1173189Z,Copying file: '.venv/bin/pip',,0
	2023-11-25T07:29:45.1535478Z,Copying file: '.venv/bin/pip3',,0
	2023-11-25T07:29:45.1767430Z,Copying file: '.venv/bin/pip3.12',,0
	2023-11-25T07:29:45.2048259Z,Copying file: '.venv/bin/sqlformat',,0
	2023-11-25T07:29:45.3401432Z,Copying file: '.venv/lib/python3.12/site-packages/Django-4.2.7.dist-info/AUTHORS',,0
	2023-11-25T07:29:45.3811615Z,Copying file: '.venv/lib/python3.12/site-packages/Django-4.2.7.dist-info/INSTALLER',,0
	2023-11-25T07:29:45.4166580Z,Copying file: '.venv/lib/python3.12/site-packages/Django-4.2.7.dist-info/LICENSE',,0
	2023-11-25T07:29:45.4562459Z,Copying file: '.venv/lib/python3.12/site-packages/Django-4.2.7.dist-info/LICENSE.python',,0
	2023-11-25T07:29:45.4861453Z,Copying file: '.venv/lib/python3.12/site-packages/Django-4.2.7.dist-info/METADATA',,0
	2023-11-25T07:29:45.5017754Z,Copying file: '.venv/lib/python3.12/site-packages/Django-4.2.7.dist-info/RECORD',,0
	2023-11-25T07:29:45.5317693Z,Copying file: '.venv/lib/python3.12/site-packages/Django-4.2.7.dist-info/REQUESTED',,0
	2023-11-25T07:29:45.5451885Z,Copying file: '.venv/lib/python3.12/site-packages/Django-4.2.7.dist-info/WHEEL',,0
	2023-11-25T07:29:45.5845362Z,Copying file: '.venv/lib/python3.12/site-packages/Django-4.2.7.dist-info/entry_points.txt',,0
	2023-11-25T07:29:45.6201198Z,Copying file: '.venv/lib/python3.12/site-packages/Django-4.2.7.dist-info/top_level.txt',,0
	2023-11-25T07:29:45.8193620Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/__init__.py',,0
	2023-11-25T07:29:45.8553926Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/compatibility.py',,0
	2023-11-25T07:29:45.8948792Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/current_thread_executor.py',,0
	2023-11-25T07:29:45.9220392Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/local.py',,0
	2023-11-25T07:29:45.9344219Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/py.typed',,0
	2023-11-25T07:29:45.9835024Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/server.py',,0
	2023-11-25T07:29:46.0303432Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/sync.py',,0
	2023-11-25T07:29:46.0579769Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/testing.py',,0
	2023-11-25T07:29:46.0925847Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/timeout.py',,0
	2023-11-25T07:29:46.1039360Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/typing.py',,0
	2023-11-25T07:29:46.1157733Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/wsgi.py',,0
	2023-11-25T07:29:46.2127656Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/__pycache__/__init__.cpython-312.pyc',,0
	2023-11-25T07:29:46.2607760Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/__pycache__/compatibility.cpython-312.pyc',,0
	2023-11-25T07:29:46.2726478Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/__pycache__/current_thread_executor.cpython-312.pyc',,0
	2023-11-25T07:29:46.2953871Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/__pycache__/local.cpython-312.pyc',,0
	2023-11-25T07:29:46.3092427Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/__pycache__/server.cpython-312.pyc',,0
	2023-11-25T07:29:46.3598954Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/__pycache__/sync.cpython-312.pyc',,0
	2023-11-25T07:29:46.4172073Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/__pycache__/testing.cpython-312.pyc',,0
	2023-11-25T07:29:46.4428317Z,Copying file: '.venv/lib/python3.12/site-packages/asgiref/__pycache__/timeout.cpython-312.pyc',,0
	2023-11-25T07:29:46.4632034Z,Omitting next output lines...,,0
	2023-11-25T07:30:06.4600222Z,Processed 330 files...,,0
	2023-11-25T07:30:26.7383622Z,Processed 597 files...,,0
	2023-11-25T07:30:46.8459116Z,Processed 1054 files...,,0
	2023-11-25T07:31:06.9317855Z,Processed 1462 files...,,0
	2023-11-25T07:31:27.0509182Z,Processed 1752 files...,,0
	2023-11-25T07:31:47.0980914Z,Processed 2056 files...,,0
	2023-11-25T07:32:07.1893803Z,Processed 2482 files...,,0
	2023-11-25T07:32:27.2969236Z,Processed 2758 files...,,0
	2023-11-25T07:32:47.3701221Z,Processed 3120 files...,,0
	2023-11-25T07:33:07.4753834Z,Processed 3456 files...,,0
	2023-11-25T07:33:27.9898053Z,Processed 3844 files...,,0
	2023-11-25T07:33:48.0572014Z,Processed 4447 files...,,0
	2023-11-25T07:34:08.1436954Z,Processed 4814 files...,,0
	2023-11-25T07:34:28.6489333Z,Processed 5382 files...,,0
	2023-11-25T07:34:48.6692074Z,Processed 5778 files...,,0
	2023-11-25T07:35:08.7035439Z,Processed 6046 files...,,0
	2023-11-25T07:35:28.7075011Z,Processed 6378 files...,,0
	2023-11-25T07:35:48.7581650Z,Processed 6679 files...,,0
	2023-11-25T07:36:08.8385418Z,Processed 7022 files...,,0
	2023-11-25T07:36:28.9722704Z,Processed 7252 files...,,0
	2023-11-25T07:36:49.0230681Z,Processed 7508 files...,,0
	2023-11-25T07:37:09.2974593Z,Processed 7783 files...,,0
	2023-11-25T07:37:29.4186666Z,Processed 8052 files...,,0
	2023-11-25T07:37:49.4620997Z,Processed 8360 files...,,0
	2023-11-25T07:38:09.5237366Z,Processed 8656 files...,,0
	2023-11-25T07:38:29.6491699Z,Processed 8892 files...,,0
	2023-11-25T07:38:49.7206608Z,Processed 9138 files...,,0
	2023-11-25T07:39:10.2551385Z,Processed 9483 files...,,0
	2023-11-25T07:39:30.3790475Z,Processed 9826 files...,,0
	2023-11-25T07:39:50.4048871Z,Processed 10240 files...,,0
	2023-11-25T07:40:10.4366243Z,Processed 10660 files...,,0
	2023-11-25T07:40:31.4543416Z,Processed 11141 files...,,0
	2023-11-25T07:40:37.9821772Z,Finished successfully.,,0
2023-11-25T07:40:38.1673837Z,Running post deployment command(s)...,af33fab1-b9ba-4d32-b1a2-54dd733fe97e,0
2023-11-25T07:40:38.3026479Z,Triggering recycle (preview mode disabled).,1608a5c8-4295-4ed1-ad5b-fa21ee57f11e,0
2023-11-25T07:40:38.5340585Z,Deployment successful. deployer = Push-Deployer deploymentPath = ZipDeploy. Extract zip.,90ab1cf1-8d6d-4be2-b9a8-259d1bb4f893,0

ローカルビルドデプロイの成果物

.venv も含め、zipファイルの中身がそのまま /home/site/wwwrootに展開されています。

アプリケーションの起動処理

アプリケーションの起動時の動作を見てみます。
なんとアプリ起動に失敗しています。

default_docker.log

2023-11-25T07:23:25.873839976Z    _____                               
2023-11-25T07:23:25.873874376Z   /  _  \ __________ _________   ____  
2023-11-25T07:23:25.873879076Z  /  /_\  \\___   /  |  \_  __ \_/ __ \ 
2023-11-25T07:23:25.873882476Z /    |    \/    /|  |  /|  | \/\  ___/ 
2023-11-25T07:23:25.873885776Z \____|__  /_____ \____/ |__|    \___  >
2023-11-25T07:23:25.873889176Z         \/      \/                  \/ 
2023-11-25T07:23:25.873892476Z A P P   S E R V I C E   O N   L I N U X
2023-11-25T07:23:25.873895376Z 
2023-11-25T07:23:25.873898176Z Documentation: http://aka.ms/webapp-linux
2023-11-25T07:23:25.873900976Z Python 3.12.0
2023-11-25T07:23:25.873903876Z Note: Any data outside '/home' is not persisted
2023-11-25T07:23:27.403389515Z Starting OpenBSD Secure Shell server: sshd.
2023-11-25T07:23:27.512991784Z App Command Line not configured, will attempt auto-detect
2023-11-25T07:23:27.749580412Z Starting periodic command scheduler: cron.
2023-11-25T07:23:27.757800555Z Launching oryx with: create-script -appPath /home/site/wwwroot -output /opt/startup/startup.sh -virtualEnvName antenv -defaultApp /opt/defaultsite
2023-11-25T07:23:27.777180455Z Could not find build manifest file at '/home/site/wwwroot/oryx-manifest.toml'
2023-11-25T07:23:27.777246156Z Could not find operation ID in manifest. Generating an operation id...
2023-11-25T07:23:27.787632909Z Build Operation ID: 9ee0aed9-4dd5-4a64-87a3-4a75bdf088a4
2023-11-25T07:23:28.341980364Z Oryx Version: 0.2.20231109.3, Commit: 07b75878a8cbe645ec942592ee7e4d443fa34cdc, ReleaseTagName: 20231109.3
2023-11-25T07:23:28.358482753Z Detected an app based on Django
2023-11-25T07:23:28.358510253Z Generating `gunicorn` command for 'quickstartproject.wsgi'
2023-11-25T07:23:28.499799112Z Writing output script to '/opt/startup/startup.sh'
2023-11-25T07:23:28.642215878Z WARNING: Could not find virtual environment directory /home/site/wwwroot/antenv.
2023-11-25T07:23:28.643108482Z WARNING: Could not find package directory /home/site/wwwroot/__oryx_packages__.
2023-11-25T07:23:29.337057012Z [2023-11-25 07:23:29 +0000] [72] [INFO] Starting gunicorn 21.2.0
2023-11-25T07:23:29.360198436Z [2023-11-25 07:23:29 +0000] [72] [INFO] Listening at: http://0.0.0.0:8000 (72)
2023-11-25T07:23:29.361261642Z [2023-11-25 07:23:29 +0000] [72] [INFO] Using worker: sync
2023-11-25T07:23:29.385717473Z [2023-11-25 07:23:29 +0000] [75] [INFO] Booting worker with pid: 75
2023-11-25T07:23:29.437395151Z [2023-11-25 07:23:29 +0000] [75] [ERROR] Exception in worker process
2023-11-25T07:23:29.437421451Z Traceback (most recent call last):
2023-11-25T07:23:29.437426951Z   File "/opt/python/3.12.0/lib/python3.12/site-packages/gunicorn/arbiter.py", line 609, in spawn_worker
2023-11-25T07:23:29.437430651Z     worker.init_process()
2023-11-25T07:23:29.437434251Z   File "/opt/python/3.12.0/lib/python3.12/site-packages/gunicorn/workers/base.py", line 134, in init_process
2023-11-25T07:23:29.437450151Z     self.load_wsgi()
2023-11-25T07:23:29.437462551Z   File "/opt/python/3.12.0/lib/python3.12/site-packages/gunicorn/workers/base.py", line 146, in load_wsgi
2023-11-25T07:23:29.437466151Z     self.wsgi = self.app.wsgi()
2023-11-25T07:23:29.437469251Z                 ^^^^^^^^^^^^^^^
2023-11-25T07:23:29.437472252Z   File "/opt/python/3.12.0/lib/python3.12/site-packages/gunicorn/app/base.py", line 67, in wsgi
2023-11-25T07:23:29.437475552Z     self.callable = self.load()
2023-11-25T07:23:29.437478552Z                     ^^^^^^^^^^^
2023-11-25T07:23:29.437481652Z   File "/opt/python/3.12.0/lib/python3.12/site-packages/gunicorn/app/wsgiapp.py", line 58, in load
2023-11-25T07:23:29.437484852Z     return self.load_wsgiapp()
2023-11-25T07:23:29.437487952Z            ^^^^^^^^^^^^^^^^^^^
2023-11-25T07:23:29.437490952Z   File "/opt/python/3.12.0/lib/python3.12/site-packages/gunicorn/app/wsgiapp.py", line 48, in load_wsgiapp
2023-11-25T07:23:29.437494352Z     return util.import_app(self.app_uri)
2023-11-25T07:23:29.437497452Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-25T07:23:29.437500552Z   File "/opt/python/3.12.0/lib/python3.12/site-packages/gunicorn/util.py", line 371, in import_app
2023-11-25T07:23:29.437503752Z     mod = importlib.import_module(module)
2023-11-25T07:23:29.437506952Z           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-25T07:23:29.437509952Z   File "/opt/python/3.12.0/lib/python3.12/importlib/__init__.py", line 90, in import_module
2023-11-25T07:23:29.437513152Z     return _bootstrap._gcd_import(name[level:], package, level)
2023-11-25T07:23:29.437516252Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-25T07:23:29.437519352Z   File "<frozen importlib._bootstrap>", line 1381, in _gcd_import
2023-11-25T07:23:29.437522852Z   File "<frozen importlib._bootstrap>", line 1354, in _find_and_load
2023-11-25T07:23:29.437526152Z   File "<frozen importlib._bootstrap>", line 1325, in _find_and_load_unlocked
2023-11-25T07:23:29.437529352Z   File "<frozen importlib._bootstrap>", line 929, in _load_unlocked
2023-11-25T07:23:29.437532552Z   File "<frozen importlib._bootstrap_external>", line 994, in exec_module
2023-11-25T07:23:29.437535652Z   File "<frozen importlib._bootstrap>", line 488, in _call_with_frames_removed
2023-11-25T07:23:29.437538852Z   File "/home/site/wwwroot/quickstartproject/wsgi.py", line 12, in <module>
2023-11-25T07:23:29.437542152Z     from django.core.wsgi import get_wsgi_application
2023-11-25T07:23:29.437546352Z ModuleNotFoundError: No module named 'django'
2023-11-25T07:23:29.446315899Z [2023-11-25 07:23:29 +0000] [75] [INFO] Worker exiting (pid: 75)
2023-11-25T07:23:29.675514631Z [2023-11-25 07:23:29 +0000] [72] [ERROR] Worker (pid:75) exited with code 3
2023-11-25T07:23:29.682669469Z [2023-11-25 07:23:29 +0000] [72] [ERROR] Shutting down: Master
2023-11-25T07:23:29.683373073Z [2023-11-25 07:23:29 +0000] [72] [ERROR] Reason: Worker failed to boot.

ModuleNotFoundError: No module named 'django' とあります。/home/site/wwwroot.venv 以下にSitePackageとして含めてあるはずなのに。

理由はこれ

2023-11-25T07:23:28.642215878Z WARNING: Could not find virtual environment directory /home/site/wwwroot/antenv.
2023-11-25T07:23:28.643108482Z WARNING: Could not find package directory /home/site/wwwroot/__oryx_packages__.

WEBSITES_CONTAINER_START_TIME_LIMIT に 1200 カスタムスタートアップコマンドに sleep 1200; を設定して、コンテナ起動を遅延させてSSHして起動スクリプトを見てみます。

antenv という名前の仮想環境であることが前提になっています。

/opt/startup/startup.sh

root@c8f202bb0cfa:/home/site/wwwroot# cat /opt/startup/startup.sh 
#!/bin/sh

echo 'export APP_PATH="/home/site/wwwroot"' >> ~/.bashrc
echo 'cd $APP_PATH' >> ~/.bashrc

# Enter the source directory to make sure the script runs where the user expects
cd /home/site/wwwroot

export APP_PATH="/home/site/wwwroot"
if [ -z "$HOST" ]; then
                export HOST=0.0.0.0
fi

if [ -z "$PORT" ]; then
                export PORT=80
fi

export PATH="/opt/python//bin:${PATH}"
echo 'export VIRTUALENVIRONMENT_PATH="/home/site/wwwroot/antenv"' >> ~/.bashrc
echo '. antenv/bin/activate' >> ~/.bashrc
  echo WARNING: Could not find virtual environment directory '/home/site/wwwroot/antenv'.
  echo WARNING: Could not find package directory '/home/site/wwwroot/__oryx_packages__'.
PATH="$PATH:/home/site/wwwroot" sleep 1200;

対応策

ヒントは GitHub Actions にあります。

  # install dependencies
  - name: python install
    working-directory: ${{ env.WORKING_DIRECTORY }}
    run: |
     sudo apt install python${{ env.PYTHON_VERSION }}-venv
     python -m venv --copies antenv
     source antenv/bin/activate
     pip install setuptools
     pip install -r requirements.txt

というわけで、.venv ではなく antenv という名称で仮想環境をつくります。

python -m venv --copies antenv
source antenv/bin/activate
pip install -r requirements.txt

.venv はいらないので、zip を作り直します。このとき antenv は含めます。

zip -r ../zipDeployRelease_antenv.zip . --exclude "./.venv/*" "./.git/*" "./.vscode/*" ".devcontainer/*" ".github/*" ".deployment"
curl -u "$basicAuthInfo"  -X POST -T ../zipDeployRelease_antenv.zip "https://python-remote-build.scm.azurewebsites.net/api/zipdeploy?clean=true&restart=true&isAsync=true" -v

これで起動まではできる。しかしまだ何かおかしい。

2023-11-25T08:37:45.698234174Z    _____                               
2023-11-25T08:37:45.698290974Z   /  _  \ __________ _________   ____  
2023-11-25T08:37:45.698297574Z  /  /_\  \\___   /  |  \_  __ \_/ __ \ 
2023-11-25T08:37:45.698301474Z /    |    \/    /|  |  /|  | \/\  ___/ 
2023-11-25T08:37:45.698305274Z \____|__  /_____ \____/ |__|    \___  >
2023-11-25T08:37:45.698309074Z         \/      \/                  \/ 
2023-11-25T08:37:45.698312574Z A P P   S E R V I C E   O N   L I N U X
2023-11-25T08:37:45.698315874Z 
2023-11-25T08:37:45.698319274Z Documentation: http://aka.ms/webapp-linux
2023-11-25T08:37:45.698322574Z Python 3.12.0
2023-11-25T08:37:45.698325774Z Note: Any data outside '/home' is not persisted
2023-11-25T08:37:47.379115349Z Starting OpenBSD Secure Shell server: sshd.
2023-11-25T08:37:47.537827459Z App Command Line not configured, will attempt auto-detect
2023-11-25T08:37:47.829272046Z Starting periodic command scheduler: cron.
2023-11-25T08:37:47.831696358Z Launching oryx with: create-script -appPath /home/site/wwwroot -output /opt/startup/startup.sh -virtualEnvName antenv -defaultApp /opt/defaultsite
2023-11-25T08:37:47.912342670Z Could not find build manifest file at '/home/site/wwwroot/oryx-manifest.toml'
2023-11-25T08:37:47.913624776Z Could not find operation ID in manifest. Generating an operation id...
2023-11-25T08:37:47.915388785Z Build Operation ID: 5a301507-d1de-4f2f-8254-84302b3762da
2023-11-25T08:37:48.610783795Z Oryx Version: 0.2.20231109.3, Commit: 07b75878a8cbe645ec942592ee7e4d443fa34cdc, ReleaseTagName: 20231109.3
2023-11-25T08:37:48.620843746Z Detected an app based on Django
2023-11-25T08:37:48.620863646Z Generating `gunicorn` command for 'quickstartproject.wsgi'
2023-11-25T08:37:48.742029955Z Writing output script to '/opt/startup/startup.sh'
2023-11-25T08:37:49.023530171Z Using packages from virtual environment antenv located at /home/site/wwwroot/antenv.
2023-11-25T08:37:49.024784477Z Updated PYTHONPATH to '/opt/startup/app_logs:/home/site/wwwroot/antenv/lib/python3.12/site-packages'
2023-11-25T08:37:49.772587438Z [2023-11-25 08:37:49 +0000] [73] [INFO] Starting gunicorn 21.2.0
2023-11-25T08:37:49.796523959Z [2023-11-25 08:37:49 +0000] [73] [INFO] Listening at: http://0.0.0.0:8000 (73)
2023-11-25T08:37:49.797338863Z [2023-11-25 08:37:49 +0000] [73] [INFO] Using worker: sync
2023-11-25T08:37:49.811437334Z [2023-11-25 08:37:49 +0000] [76] [INFO] Booting worker with pid: 76
2023-11-25T08:38:02.814325563Z /home/site/wwwroot/antenv/lib/python3.12/site-packages/django/core/handlers/base.py:61: UserWarning: No directory at: /home/site/wwwroot/staticfiles/
2023-11-25T08:38:02.814516864Z   mw_instance = middleware(adapted_handler)
2023-11-25T08:38:04.239381898Z 169.254.130.1 - - [25/Nov/2023:08:38:04 +0000] "GET /robots933456.txt HTTP/1.1" 400 143 "-" "HealthCheck/1.0"
2023-11-25T08:38:04.494145176Z 169.254.130.1 - - [25/Nov/2023:08:38:04 +0000] "GET /favicon.ico HTTP/1.1" 404 179 "https://python-remote-build.azurewebsites.net/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/119.0.0.0 Safari/537.36 Edg/119.0.0.0"

2023-11-25T08:39:07.754877276Z Request for index page received
2023-11-25T08:39:07.754947877Z 169.254.130.1 - - [25/Nov/2023:08:39:07 +0000] "GET / HTTP/1.1" 500 145 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/119.0.0.0 Safari/537.36 Edg/119.0.0.0"

2023-11-25T08:39:09.568406749Z Request for index page received
2023-11-25T08:39:09.568446549Z 169.254.130.1 - - [25/Nov/2023:08:39:09 +0000] "GET / HTTP/1.1" 500 145 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/119.0.0.0 Safari/537.36 Edg/119.0.0.0"
2023-11-25T08:39:10.703648578Z Request for index page received
2023-11-25T08:39:10.703697178Z 169.254.130.1 - - [25/Nov/2023:08:39:10 +0000] "GET / HTTP/1.1" 500 145 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/119.0.0.0 Safari/537.36 Edg/119.0.0.0"
2023-11-25T08:39:11.505169223Z Request for index page received
2023-11-25T08:39:11.511896257Z 169.254.130.1 - - [25/Nov/2023:08:39:11 +0000] "GET / HTTP/1.1" 500 145 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/119.0.0.0 Safari/537.36 Edg/119.0.0.0"

2023-11-25T08:39:22.172217378Z Request for index page received
2023-11-25T08:39:22.172273978Z 169.254.130.1 - - [25/Nov/2023:08:39:22 +0000] "GET / HTTP/1.1" 500 145 "https://python-remote-build.scm.azurewebsites.net/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/119.0.0.0 Safari/537.36 Edg/119.0.0.0"

500 Error の原因と対策

以下の manage.py の推測は誤り。

~~サンプルアプリを確認すると manage.py に以下の記述がある。~~

manage.py

settings_module = 'quickstartproject.production' if 'WEBSITE_HOSTNAME' in os.environ else 'quickstartproject.settings'

~~これによって読み込まれるファイルは~~

~~Azure上(if 'WEBSITE_HOSTNAME' in os.environ) では~~
~~production.py~~
ローカルでは
~~settings.py~~
~~となる。~~

~~単純に production.py に必要な情報が足りていないだけと思われる。~~
~~production.py 側に settings.py に記載の構成情報を足してデプロイすると正常に動作した。~~

ただ、リモートビルドの時はどうして問題なく動いたのかが疑問なので後で調べる。
↓

ログをよく見ると以下の記述がある。

2023-11-25T08:38:02.814325563Z /home/site/wwwroot/antenv/lib/python3.12/site-packages/django/core/handlers/base.py:61: UserWarning: No directory at: /home/site/wwwroot/staticfiles/

staticfiles がないとのこと。
リモートビルドの時は、Oryx が生成してくれていた。

If manage.py is found in the root of the repo manage.py collectstatic is run. However, if DISABLE_COLLECTSTATIC is set to true this step is skipped.

そのため、ローカルビルドデプロイする場合は、zip モジュール作成前にローカルで作成しておく必要がある。

python manage.py collectstatic
zip -r ../zipDeployRelease.zip . --exclude "./.venv/*" "./.git/*" "./.vscode/*" ".devcontainer/*" ".github/*" ".deployment"
curl -u "$basicAuthInfo"  -X POST -T ../zipDeployRelease.zip "https://python-remote-build.scm.azurewebsites.net/api/zipdeploy?clean=true&restart=true&isAsync=true" -v

これで問題なく動作しました。めでたしめでたし。

考察

素直にリモートビルド使っておこうとなりますが、リモートビルドに必要な Network dependencies を NSG やら Firewall なりで防いでいる場合は、必要なモジュールはあらかじめ全部用意しておく必要があるということですね。