Flask app failure happens days after deployment

[KevinXTian]

I have an Azure Linux App Service running with code deployment and Always On: False. The app service works as expected right after deployment, and failed with 503 errors after a certain amount of time. When a 503 error is observed, the stream log from the app service shows the following error message.

2018-11-13 15:24:58.731 INFO  - Starting container for site
2018-11-13 15:24:58.733 INFO  - docker run -d -p 43438:8000 --name usagedriverdevlinux_0 -e WEBSITE_SITE_NAME=usagedriverdevlinux -e WEBSITE_AUTH_ENABLED=False -e WEBSITE_ROLE_INSTANCE_ID=0 -e WEBSITE_INSTANCE_ID=ecd7b7595c2085f900b2a30ce059050e5bc2dcf3927d1ef3f9745e96bd1fef71 -e HTTP_LOGGING_ENABLED=1 appsvc/python:3.6.6_1809042203
2018-11-13T15:24:59.092415149Z
2018-11-13T15:24:59.092541749Z   _____
2018-11-13T15:24:59.092546749Z   /  _  \ __________ _________   ____
2018-11-13T15:24:59.092550249Z  /  /_\  \___   /  |  \_  __ \_/ __ \
2018-11-13T15:24:59.092553849Z /    |    \/    /|  |  /|  | \/\  ___/
2018-11-13T15:24:59.092557349Z \____|__  /_____ \____/ |__|    \___  >
2018-11-13T15:24:59.092560949Z         \/      \/                  \/
2018-11-13T15:24:59.092564349Z
2018-11-13T15:24:59.092575449Z A P P   S E R V I C E   O N   L I N U X
2018-11-13T15:24:59.092579649Z
2018-11-13T15:24:59.092582849Z Documentation: http://aka.ms/webapp-linux
2018-11-13T15:24:59.092586049Z NodeJS quickstart: https://aka.ms/node-qs
2018-11-13T15:24:59.092589349Z
2018-11-13T15:24:59.149267270Z Starting OpenBSD Secure Shell server: sshd.
2018-11-13T15:24:59.156074972Z Running python /usr/local/bin/entrypoint.py
2018-11-13T15:24:59.214145894Z executing:
2018-11-13T15:24:59.214256794Z python --version
2018-11-13T15:24:59.218902596Z Python 3.6.6
2018-11-13T15:24:59.219048096Z executing:
2018-11-13T15:24:59.219130396Z pip --version
2018-11-13T15:24:59.666356263Z pip 18.0 from /usr/local/lib/python3.6/site-packages/pip (python 3.6)
2018-11-13T15:24:59.679948868Z found flask app
2018-11-13T15:24:59.680570869Z executing:
2018-11-13T15:24:59.680652269Z . antenv3.6/bin/activate
2018-11-13T15:24:59.682776670Z /bin/sh: 1: .: Can't open antenv3.6/bin/activate
2018-11-13T15:24:59.683021870Z
2018-11-13T15:24:59.683119770Z executing:
2018-11-13T15:24:59.683187170Z GUNICORN_CMD_ARGS="--bind=0.0.0.0 --timeout 600" gunicorn application:app
2018-11-13T15:24:59.900779151Z [2018-11-13 15:24:59 +0000] [33] [INFO] Starting gunicorn 19.9.0
2018-11-13T15:24:59.901405651Z [2018-11-13 15:24:59 +0000] [33] [INFO] Listening at: http://0.0.0.0:8000 (33)
2018-11-13T15:24:59.901604851Z [2018-11-13 15:24:59 +0000] [33] [INFO] Using worker: sync
2018-11-13T15:24:59.905127153Z [2018-11-13 15:24:59 +0000] [36] [INFO] Booting worker with pid: 36
2018-11-13T15:25:00.082357719Z [2018-11-13 15:25:00 +0000] [36] [ERROR] Exception in worker process
2018-11-13T15:25:00.082389219Z Traceback (most recent call last):
2018-11-13T15:25:00.082394819Z   File "/usr/local/lib/python3.6/site-packages/gunicorn/arbiter.py", line 583, in spawn_worker
2018-11-13T15:25:00.082400719Z     worker.init_process()
2018-11-13T15:25:00.082404719Z   File "/usr/local/lib/python3.6/site-packages/gunicorn/workers/base.py", line 129, in init_process
2018-11-13T15:25:00.082408919Z     self.load_wsgi()
2018-11-13T15:25:00.082412819Z   File "/usr/local/lib/python3.6/site-packages/gunicorn/workers/base.py", line 138, in load_wsgi
2018-11-13T15:25:00.082424919Z     self.wsgi = self.app.wsgi()
2018-11-13T15:25:00.082429119Z   File "/usr/local/lib/python3.6/site-packages/gunicorn/app/base.py", line 67, in wsgi
2018-11-13T15:25:00.082433019Z     self.callable = self.load()
2018-11-13T15:25:00.082436819Z   File "/usr/local/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 52, in load
2018-11-13T15:25:00.082440719Z     return self.load_wsgiapp()
2018-11-13T15:25:00.082444419Z   File "/usr/local/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 41, in load_wsgiapp
2018-11-13T15:25:00.082448319Z     return util.import_app(self.app_uri)
2018-11-13T15:25:00.082452119Z   File "/usr/local/lib/python3.6/site-packages/gunicorn/util.py", line 350, in import_app
2018-11-13T15:25:00.082456019Z     __import__(module)
2018-11-13T15:25:00.082459719Z   File "/home/site/wwwroot/application.py", line 6, in <module>
2018-11-13T15:25:00.082464019Z     from flask_httpauth import HTTPBasicAuth
2018-11-13T15:25:00.082467919Z ModuleNotFoundError: No module named 'flask_httpauth'
2018-11-13T15:25:00.082950219Z [2018-11-13 15:25:00 +0000] [36] [INFO] Worker exiting (pid: 36)
2018-11-13T15:25:00.124758235Z [2018-11-13 15:25:00 +0000] [33] [INFO] Shutting down: Master
2018-11-13T15:25:00.125010935Z [2018-11-13 15:25:00 +0000] [33] [INFO] Reason: Worker failed to boot.
2018-11-13T15:25:00.157341247Z
2018-11-13 15:25:01.155 ERROR - Container usagedriverdevlinux_0 for site usagedriverdevlinux has exited, failing site startStatus_WatchFile :: Error Error: ENOENT: no such file or directory, open '/appsvctmp/status.txt'

The problem is solved by switching Always On: True. I suspect that the right virtual environment works right after the deployment. When Always On is turned off, the container is destroyed after a certain amount of time. Then when a new request coming, a container is being created but fails in creating the virtual environment. Then the default Python, who did not install dependencies from requirements.txt, is called. Then ModuleNotFoundError is shown.

By setting Always On to True, the container is always running and the virtual environment created in the container works as well. So that problem is temporary solved.

For more detailed information, please check support ticket [REG:118111321002576]. I really appreciate the help from MSFT support engineers Ramya Gangula and Prashanth Madi in figuring out the possible causes.

[KevinXTian]

Any update on this one?

[JennyLawrance]

@KevinXTian
I'll have to reproduce this behavior and see for myself why this failure happens. Are you deploying a simple flask app? Also, was the initial deployment done with git or FTP?

[KevinXTian]

Yes, it is a simple flask app. And the initial deployment is done with git.

…

________________________________ From: JennyLawrance <[email protected]> Sent: Friday, December 7, 2018 8:57 PM To: Azure-App-Service/python Cc: Tian, Xueli (Kevin); Mention Subject: Re: [Azure-App-Service/python] Flask app failure happens days after deployment (#13) @KevinXTian<https://github.com/KevinXTian> I'll have to reproduce this behavior and see for myself why this failure happens. Are you deploying a simple flask app? Also, was the initial deployment done with git or FTP? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub<#13 (comment)>, or mute the thread<https://github.com/notifications/unsubscribe-auth/Afr9NAg9JxI85SD8jWHKwnPDkhHqzBtAks5u2xx1gaJpZM4Ym231>.

[JennyLawrance]

I have a theory for this failure: Essentially, we have an issue / disconnect between the UX and the runtime, where UX allowed python 3.6 to be selected while the runtime was not yet upgraded. This meant that, for this site, the runtime 3.6 version was only available after 11/14 on that scale unit, and I believe you also did a Virtual Environmet create with SSH portal to get the site back to an operational state.
When the site was deployed, the Virtual Environment created was for 3.7/ But when 3.6 runtime was loaded after the upgrade, the site failed to start, since it looks for a different virtual environment. I'll continue to investigate this next week, but I'm pretty certain that alwaysOn in this case is a red-herring, and is not what has resolved the issue.