Azure App Service slow startup - if any - due to warmup timeout

Viewed 1241

I am trying to deploy a Python application as an Azure App Service trough a DevOps Pipeline as described here below:

trigger:
- master

pool:
  vmImage: 'ubuntu-latest'
strategy:
  matrix:
    Python38:
      python.version: '3.8'

steps:
- task: UsePythonVersion@0
  inputs:
    versionSpec: '$(python.version)'
  displayName: 'Use Python $(python.version)'

- script: |
    python -m venv antenv
    source antenv/bin/activate
    python -m pip install --upgrade pip
    pip install -r requirements.txt
  workingDirectory: '$(System.DefaultWorkingDirectory)'
  displayName: 'Install dependencies'

- task: ArchiveFiles@2
  inputs:
    rootFolderOrFile: '$(System.DefaultWorkingDirectory)'
    includeRootFolder: false
    archiveType: 'zip'
    archiveFile: '$(Build.ArtifactStagingDirectory)/$(Build.BuildId).zip'
    replaceExistingArchive: true
  displayName: 'Archive (zip) build'

- task: PublishBuildArtifacts@1
  inputs:
    PathtoPublish: '$(Build.ArtifactStagingDirectory)/$(Build.BuildId).zip'
    ArtifactName: 'drop'
    publishLocation: 'Container'
  displayName: 'Upload package'

- task: AzureRmWebAppDeployment@4
  inputs:
    ConnectionType: 'AzureRM'
    azureSubscription: 'My Azure service connection'
    appType: 'webAppLinux'
    WebAppName: 'my-app-name'
    packageForLinux: '$(Build.ArtifactStagingDirectory)/$(Build.BuildId).zip'
    RuntimeStack: 'PYTHON|3.8'
    StartupCommand: 'python -m uvicorn module_name.app:app --host 0.0.0.0'
    AppSettings: '-AZURE_STORAGE_CONNECTION_STRING DefaultEndpointsProtocol=https;AccountName=foo;AccountKey=bar;EndpointSuffix=core.windows.net'
  displayName: 'Deploy to App Service'

The pipeline runs completely fine, although the AzureRmWebAppDeployment task runs slow (about 10 minutes each run).The pipeline completes however without further issues.

When I run the pipeline and try to access my app through my-app-name.azurewebsites.net it starts to load for a long time. If I check the log stream I see a warmup issue which occurs everytime I now try to access my web app:

2020-10-29T08:03:50.364Z INFO  - Logging is not enabled for this container.Please use https://aka.ms/linux-diagnostics to enable logging to see container logs here.
2020-10-29T08:03:53.540Z INFO  - Initiating warmup request to container my-app-name_0_d3110f5d for site my-app-name
2020-10-29T08:04:10.812Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 17.2725268 sec
2020-10-29T08:04:26.219Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 32.680095 sec
2020-10-29T08:04:41.715Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 48.1755114 sec
2020-10-29T08:04:57.101Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 63.5620041 sec
2020-10-29T08:05:12.818Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 79.2786992 sec
2020-10-29T08:05:28.865Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 95.3258608 sec
2020-10-29T08:05:44.566Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 111.0266762 sec
2020-10-29T08:06:00.349Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 126.8094449 sec
2020-10-29T08:06:19.588Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 146.0265159 sec
2020-10-29T08:06:49.023Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 175.4822751 sec
2020-10-29T08:07:18.829Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 205.2596723 sec
2020-10-29T08:07:43.147Z INFO  - Waiting for response to warmup request for container my-app-name_0_d3110f5d. Elapsed time = 229.5953375 sec
2020-10-29T08:03:53.660669027Z
2020-10-29T08:03:53.660723628Z   _____
2020-10-29T08:03:53.660735429Z   /  _  \ __________ _________   ____
2020-10-29T08:03:53.660815632Z  /  /_\  \___   /  |  \_  __ \_/ __ \
2020-10-29T08:03:53.660887234Z /    |    \/    /|  |  /|  | \/\  ___/
2020-10-29T08:03:53.660896034Z \____|__  /_____ \____/ |__|    \___  >
2020-10-29T08:03:53.660904035Z         \/      \/                  \/
2020-10-29T08:03:53.660911835Z
2020-10-29T08:03:53.660918835Z A P P   S E R V I C E   O N   L I N U X
2020-10-29T08:03:53.660925835Z
2020-10-29T08:03:53.660932636Z Documentation: http://aka.ms/webapp-linux
2020-10-29T08:03:53.660939736Z Python 3.8.5
2020-10-29T08:03:53.660947036Z Note: Any data outside '/home' is not persisted
2020-10-29T08:03:54.101015818Z Starting OpenBSD Secure Shell server: sshd.
2020-10-29T08:03:54.173129656Z Site's appCommandLine: python -m uvicorn module_name.app:app --host 0.0.0.0
2020-10-29T08:03:54.173830580Z Launching oryx with: create-script -appPath /home/site/wwwroot -output /opt/startup/startup.sh -virtualEnvName antenv -defaultApp /opt/defaultsite -userStartupCommand 'python -m uvicorn module_name.app:app --host 0.0.0.0'
2020-10-29T08:03:54.462521843Z Cound not find build manifest file at '/home/site/wwwroot/oryx-manifest.toml'
2020-10-29T08:03:54.462564344Z Could not find operation ID in manifest. Generating an operation id...
2020-10-29T08:03:54.462574144Z Build Operation ID: ef2c5971-48ed-498a-b66e-8c480d7b2541
2020-10-29T08:03:55.723914662Z Oryx Version: 0.2.20200917.1, Commit: 59deb778658a124cb74ea8e2c8f39fa87abcc9d9, ReleaseTagName: 20200917.1
2020-10-29T08:03:55.969043855Z Writing output script to '/opt/startup/startup.sh'
2020-10-29T08:03:56.449056706Z Using packages from virtual environment antenv located at /home/site/wwwroot/antenv.
2020-10-29T08:03:56.451009781Z Updated PYTHONPATH to ':/home/site/wwwroot/antenv/lib/python3.8/site-packages'
2020-10-29T08:07:59.145Z ERROR - Container my-app-name_0_d3110f5d for site my-app-name did not start within expected time limit. Elapsed time = 245.6056708 sec
2020-10-29T08:07:59.769Z ERROR - Container my-app-name_0_d3110f5d didn't respond to HTTP pings on port: 8000, failing site start. See container logs for debugging.
2020-10-29T08:08:01.109Z INFO  - Stopping site my-app-name because it failed during startup.

After these approximately three minutes of loading, my request finally gets a 502 - Web server received an invalid response while acting as a gateway or proxy server. (first time after restarting the web app or rerunning the pipeline) or an :( Application Error (thereafter).

But the weirdest part is the following. After I let it sit overnight and I checked back in the next day, boom, I could suddenly reach my app and read the OpenAPI docs (my Python app is based on FastAPI, therefore I run uvicorn). I tried this same setup again - rerun the pipeline, get the warmup issue, wait a few hours and check in again - and the same occured. After a few hours the app suddenly seems to be working but I can't find any logs indicating something worked or not.

Does someone know how to mitigate this issue? I checked some other posts which suggest I check exposed ports and the like, but I run the default uvicorn command as prescribed in the docs provided by Azure (https://docs.microsoft.com/en-us/azure/developer/python/tutorial-deploy-app-service-on-linux-04#startup-commands-for-other-frameworks-and-web-servers) which should expose the correct port (8000, setting it manually to 80 in de pipeline didn't help).

Thanks in advance!

0 Answers
Related