Tuesday, June 27, 2023

Tips for debugging Flask deployments to Azure App Service

There are many ways to deploy Flask web apps to App Service: Azure CLI, VS Code Azure Tools extension, Azure Developer CLI, or GitHub-based deployments. Unfortunately, sometimes a deploy fails, and it can be hard at first to understand what's wrong. Regardless of how you deploy Flask to App Service, you can follow these tips for debugging the deployment.

After you finish deploying, first visit the app URL to see if it loads. If it does, amazing! If it doesn't, here are steps you can take to figure out what went wrong.

Check the deployment logs

Select Deployment Center from the side navigation menu, then select Logs. You should see a timestamped list of recent deploys:

Check whether the status of the most recent deploy is "Success (Active)" or "Failed". If it's success, the deployment logs might still reveal issues, and if it's failed, the logs should certainly reveal the issue.

Click the commit ID to open the logs for the most recent deploy. First scroll down to see if any errors or warnings are reported at the end. This is what you'll hopefully see if all went well:

Now scroll back up to find the timestamp with the label "Running oryx build". Oryx is the open source tool that builds apps for App Service, Functions, and other platforms, across all the supported MS languages. Click the Show logs link next to that label. That will pop open detailed logs at the bottom. Scroll down.

Here's what a successful Oryx build looks like for a Flask application:

Command: oryx build /tmp/zipdeploy/extracted -o /home/site/wwwroot --platform python --platform-version 3.10 -p virtualenv_name=antenv --log-file /tmp/build-debug.log  -i /tmp/8db773a0e30ccc6 --compress-destination-dir | tee /tmp/oryx-build.log
Operation performed by Microsoft Oryx, https://github.com/Microsoft/Oryx
You can report issues at https://github.com/Microsoft/Oryx/issues

Oryx Version: 0.2.20230508.1, Commit: 7fe2bf39b357dd68572b438a85ca50b5ecfb4592, ReleaseTagName: 20230508.1

Build Operation ID: 164fee7dc4083f79
Repository Commit : 6e78c534-da03-414e-acc1-e396b92b1405
OS Type           : bullseye
Image Type        : githubactions

Detecting platforms...
Detected following platforms:
  python: 3.10.8
Version '3.10.8' of platform 'python' is not installed. Generating script to install it...

Using intermediate directory '/tmp/8db773a0e30ccc6'.

Copying files to the intermediate directory...
Done in 0 sec(s).

Source directory     : /tmp/8db773a0e30ccc6
Destination directory: /home/site/wwwroot

Downloading and extracting 'python' version '3.10.8' to '/tmp/oryx/platforms/python/3.10.8'...
Detected image debian flavor: bullseye.
Downloaded in 2 sec(s).
Verifying checksum...
Extracting contents...
performing sha512 checksum for: python...
Done in 18 sec(s).

image detector file exists, platform is python..
OS detector file exists, OS is bullseye..
Python Version: /tmp/oryx/platforms/python/3.10.8/bin/python3.10
Creating directory for command manifest file if it does not exist
Removing existing manifest file
Python Virtual Environment: antenv
Creating virtual environment...
Activating virtual environment...
Running pip install...
[18:13:30+0000] Collecting Flask==2.3.2
[18:13:30+0000]   Downloading Flask-2.3.2-py3-none-any.whl (96 kB)
[18:13:30+0000]      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 96.9/96.9 kB 4.8 MB/s eta 0:00:00
[18:13:31+0000] Collecting itsdangerous>=2.1.2
[18:13:31+0000]   Downloading itsdangerous-2.1.2-py3-none-any.whl (15 kB)
[18:13:31+0000] Collecting click>=8.1.3
[18:13:31+0000]   Downloading click-8.1.3-py3-none-any.whl (96 kB)
[18:13:31+0000]      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 96.6/96.6 kB 5.4 MB/s eta 0:00:00
[18:13:31+0000] Collecting Werkzeug>=2.3.3
[18:13:31+0000]   Downloading Werkzeug-2.3.6-py3-none-any.whl (242 kB)
[18:13:31+0000]      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 242.5/242.5 kB 8.7 MB/s eta 0:00:00
[18:13:31+0000] Collecting blinker>=1.6.2
[18:13:31+0000]   Downloading blinker-1.6.2-py3-none-any.whl (13 kB)
[18:13:31+0000] Collecting Jinja2>=3.1.2
[18:13:31+0000]   Downloading Jinja2-3.1.2-py3-none-any.whl (133 kB)
[18:13:31+0000]      ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 133.1/133.1 kB 6.9 MB/s eta 0:00:00
[18:13:32+0000] Collecting MarkupSafe>=2.0
[18:13:32+0000]   Downloading MarkupSafe-2.1.3-cp310-cp310-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (25 kB)
[18:13:33+0000] Installing collected packages: MarkupSafe, itsdangerous, click, blinker, Werkzeug, Jinja2, Flask
[18:13:35+0000] Successfully installed Flask-2.3.2 Jinja2-3.1.2 MarkupSafe-2.1.3 Werkzeug-2.3.6 blinker-1.6.2 click-8.1.3 itsdangerous-2.1.2

[notice] A new release of pip available: 22.2.2 -> 23.1.2
[notice] To update, run: pip install --upgrade pip
Not a vso image, so not writing build commands
Preparing output...

Copying files to destination directory '/tmp/_preCompressedDestinationDir'...
Done in 3 sec(s).
Compressing content of directory '/tmp/_preCompressedDestinationDir'...
Copied the compressed output to '/home/site/wwwroot'

Removing existing manifest file
Creating a manifest file...
Manifest file created.
Copying .ostype to manifest output directory.

Done in 70 sec(s).

Look for these important steps in the Oryx build:

  • Detected following platforms: python: 3.10.8
    That should match your runtime in the App Service configuration.
  • Running pip install...
    That should install all the requirements in your requirements.txt - if it didn't find your requirements.txt, then you won't see the packages installed.

If you see all those steps in the Oryx build, then that's a good sign that the build went well, and you can move on to checking the App Service logs.

Check the log stream

Under the Monitoring section of the side nav, select Log stream. Scroll to the timestamp corresponding to your most recent deploy.

The logs should start with pulling Docker images:

Screenshot of Log stream in App Service

Here are the full logs for a Flask app successfully starting in an App Service container:

2023-06-27T20:00:33.556Z INFO  - 3.10_20230519.2.tuxprod Pulling from appsvc/python
2023-06-27T20:00:33.559Z INFO  -  Digest: sha256:d7f1824d43ab89f90ec317f32a801ecffd4321a3d4a710593658be9bd980cd22
2023-06-27T20:00:33.560Z INFO  -  Status: Image is up to date for mcr.microsoft.com/appsvc/python:3.10_20230519.2.tuxprod
2023-06-27T20:00:33.563Z INFO  - Pull Image successful, Time taken: 0 Minutes and 0 Seconds
2023-06-27T20:00:34.710Z INFO  - Starting container for site
2023-06-27T20:00:34.711Z INFO  - docker run -d --expose=8000 --name flask-server-core-7icehkhjdeox2-appservice_5_edde42ea -e WEBSITE_CORS_ALLOWED_ORIGINS=https://portal.azure.com,https://ms.portal.azure.com -e WEBSITE_CORS_SUPPORT_CREDENTIALS=False -e WEBSITE_SITE_NAME=flask-server-core-7icehkhjdeox2-appservice -e WEBSITE_AUTH_ENABLED=False -e WEBSITE_ROLE_INSTANCE_ID=0 -e WEBSITE_HOSTNAME=flask-server-core-7icehkhjdeox2-appservice.azurewebsites.net -e WEBSITE_INSTANCE_ID=a822bcb6dd314caab4bd83084cc7a3991e4965ec4f97b7ce99c0ca46861dc419 -e HTTP_LOGGING_ENABLED=1 -e WEBSITE_USE_DIAGNOSTIC_SERVER=False appsvc/python:3.10_20230519.2.tuxprod  
2023-06-27T20:00:37.357175818Z    _____                               
2023-06-27T20:00:37.357230418Z   /  _  \ __________ _________   ____  
2023-06-27T20:00:37.357235518Z  /  /_\  \\___   /  |  \_  __ \_/ __ \ 
2023-06-27T20:00:37.357239618Z /    |    \/    /|  |  /|  | \/\  ___/ 
2023-06-27T20:00:37.357243418Z \____|__  /_____ \____/ |__|    \___  >
2023-06-27T20:00:37.357247318Z         \/      \/                  \/ 
2023-06-27T20:00:37.357251218Z A P P   S E R V I C E   O N   L I N U X
2023-06-27T20:00:37.357258418Z Documentation: http://aka.ms/webapp-linux
2023-06-27T20:00:37.357261918Z Python 3.10.11
2023-06-27T20:00:37.357282418Z Note: Any data outside '/home' is not persisted
2023-06-27T20:00:41.641875105Z Starting OpenBSD Secure Shell server: sshd.
2023-06-27T20:00:41.799900179Z App Command Line not configured, will attempt auto-detect
2023-06-27T20:00:42.761658829Z Starting periodic command scheduler: cron.
2023-06-27T20:00:42.761688529Z Launching oryx with: create-script -appPath /home/site/wwwroot -output /opt/startup/startup.sh -virtualEnvName antenv -defaultApp /opt/defaultsite
2023-06-27T20:00:42.876778283Z Found build manifest file at '/home/site/wwwroot/oryx-manifest.toml'. Deserializing it...
2023-06-27T20:00:42.887163588Z Build Operation ID: 820645c3a1e60b5e
2023-06-27T20:00:42.890123289Z Oryx Version: 0.2.20230512.3, Commit: a81ce1fa16b6e03d37f79d3ba5e99cf09b28e4ef, ReleaseTagName: 20230512.3
2023-06-27T20:00:42.897199993Z Output is compressed. Extracting it...
2023-06-27T20:00:42.964545124Z Extracting '/home/site/wwwroot/output.tar.gz' to directory '/tmp/8db774903eba755'...
2023-06-27T20:00:46.203967540Z App path is set to '/tmp/8db774903eba755'
2023-06-27T20:00:46.728397586Z Detected an app based on Flask
2023-06-27T20:00:46.730162987Z Generating `gunicorn` command for 'app:app'
2023-06-27T20:00:46.770331805Z Writing output script to '/opt/startup/startup.sh'
2023-06-27T20:00:47.050828437Z Using packages from virtual environment antenv located at /tmp/8db774903eba755/antenv.
2023-06-27T20:00:47.052387737Z Updated PYTHONPATH to '/opt/startup/app_logs:/tmp/8db774903eba755/antenv/lib/python3.10/site-packages'
2023-06-27T20:00:50.406265801Z [2023-06-27 20:00:50 +0000] [67] [INFO] Starting gunicorn 20.1.0
2023-06-27T20:00:50.434991028Z [2023-06-27 20:00:50 +0000] [67] [INFO] Listening at: (67)
2023-06-27T20:00:50.441222333Z [2023-06-27 20:00:50 +0000] [67] [INFO] Using worker: sync
2023-06-27T20:00:50.473174263Z [2023-06-27 20:00:50 +0000] [70] [INFO] Booting worker with pid: 70
2023-06-27T20:00:53.772011632Z - - [27/Jun/2023:20:00:53 +0000] "GET /robots933456.txt HTTP/1.1" 404 91 "-" "HealthCheck/1.0"
2023-06-27T20:00:55.268900825Z - - [27/Jun/2023:20:00:55 +0000] "GET /robots933456.txt HTTP/1.1" 404 91 "-" "HealthCheck/1.0"

2023-06-27T20:01:47.691011982Z - - [27/Jun/2023:20:01:47 +0000] "GET /hello HTTP/1.1" 200 183 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/ Safari/537.36 Edg/113.0.1774.57"

A few notable logs:

  • 2023-06-27T18:22:17.803525340Z Detected an app based on Flask
    This log indicates that Oryx auto-detected a Flask app (by inspecting the requirements.txt) file.
  • 2023-06-27T18:22:17.803557841Z Generating `gunicorn` command for 'app:app'
    This indicates the Oryx detected an app.py file and assumes it has an app object inside it.
  • 2023-06-27T18:22:42.540158812Z [2023-06-27 18:22:42 +0000] [67] [INFO] Starting gunicorn 20.1.0
    That's the start of the gunicorn server serving the Flask app. After it starts, the logs should show HTTP requests.

If you aren't seeing the full logs, it's possible that your deploy happened too long ago and the portal has deleted some logs. In that case, open the Log stream and do another deploy, and you should see the full logs.

Alternatively, you can download the full logs from the Kudu interface. Select Advanced Tools from the side nav:

Screenshot of Azure Portal side nav with Advanced Tools selected

When the Kudu website loads, find the Current Docker Logs link and select Download as zip next to it:

Screenshot of website list of links

In the downloaded zip file, find the filename that starts with the most recent date and ends with "_default_docker.log":

Screenshot of extracted zip folder with files

Open that file to see the full logs, with the most recent logs at the bottom.

No comments: