azure-search-openai-demo icon indicating copy to clipboard operation
azure-search-openai-demo copied to clipboard

app runs locally but not on azure

Open MarPeg53 opened this issue 1 year ago • 11 comments

Please provide us with the following information:

This issue is for a: (mark with an x)

- [x] bug report -> please search issues before submitting
- [ ] feature request
- [ ] documentation issue or request
- [ ] regression (a behavior that used to work and stopped in a new release)

Minimal steps to reproduce

I made small adjustments in the backend and imported some modules. The app runs locally without problems but not on azure. I'm getting the error ModuleNotFoundError: No module named 'main'

Any log messages given by the failure

2023-11-13T15:00:51.048245136Z Documentation: http://aka.ms/webapp-linux 2023-11-13T15:00:51.048248537Z Python 3.11.4 2023-11-13T15:00:51.048252037Z Note: Any data outside '/home' is not persisted 2023-11-13T15:00:53.841410117Z Starting OpenBSD Secure Shell server: sshd. 2023-11-13T15:00:54.079495903Z Site's appCommandLine: python3 -m gunicorn main:app 2023-11-13T15:00:54.080804907Z Launching oryx with: create-script -appPath /home/site/wwwroot -output /opt/startup/startup.sh -virtualEnvName antenv -defaultApp /opt/defaultsite -userStartupCommand 'python3 -m gunicorn main:app' 2023-11-13T15:00:54.249114991Z Could not find build manifest file at '/home/site/wwwroot/oryx-manifest.toml' 2023-11-13T15:00:54.249849694Z Could not find operation ID in manifest. Generating an operation id... 2023-11-13T15:00:54.258543119Z Build Operation ID: 23ac646d-8475-407f-9678-e9a68c100d0c 2023-11-13T15:00:54.932481259Z Oryx Version: 0.2.20230707.1, Commit: 0bd28e69919b5e8beba451e8677e3345f0be8361, ReleaseTagName: 20230707.1 2023-11-13T15:00:55.020314512Z Writing output script to '/opt/startup/startup.sh' 2023-11-13T15:00:55.144179167Z WARNING: Could not find virtual environment directory /home/site/wwwroot/antenv. 2023-11-13T15:00:55.151022287Z WARNING: Could not find package directory /home/site/wwwroot/oryx_packages. 2023-11-13T15:01:02.485772081Z [2023-11-13 15:01:02 +0000] [59] [INFO] Starting gunicorn 20.1.0 2023-11-13T15:01:02.507425354Z [2023-11-13 15:01:02 +0000] [59] [INFO] Listening at: http://0.0.0.0:8000 (59) 2023-11-13T15:01:02.507455954Z [2023-11-13 15:01:02 +0000] [59] [INFO] Using worker: sync 2023-11-13T15:01:02.720012673Z [2023-11-13 15:01:02 +0000] [65] [INFO] Booting worker with pid: 65 2023-11-13T15:01:02.807577969Z [2023-11-13 15:01:02 +0000] [65] [ERROR] Exception in worker process 2023-11-13T15:01:02.807624769Z Traceback (most recent call last): 2023-11-13T15:01:02.807630869Z File "/opt/python/3/lib/python3.11/site-packages/gunicorn/arbiter.py", line 589, in spawn_worker 2023-11-13T15:01:02.807634869Z worker.init_process() 2023-11-13T15:01:02.807638569Z File "/opt/python/3/lib/python3.11/site-packages/gunicorn/workers/base.py", line 134, in init_process 2023-11-13T15:01:02.807648869Z self.load_wsgi() 2023-11-13T15:01:02.807653669Z File "/opt/python/3/lib/python3.11/site-packages/gunicorn/workers/base.py", line 146, in load_wsgi 2023-11-13T15:01:02.807669369Z self.wsgi = self.app.wsgi() 2023-11-13T15:01:02.807673869Z ^^^^^^^^^^^^^^^ 2023-11-13T15:01:02.807677269Z File "/opt/python/3/lib/python3.11/site-packages/gunicorn/app/base.py", line 67, in wsgi 2023-11-13T15:01:02.807680969Z self.callable = self.load() 2023-11-13T15:01:02.807684369Z ^^^^^^^^^^^ 2023-11-13T15:01:02.807687769Z File "/opt/python/3/lib/python3.11/site-packages/gunicorn/app/wsgiapp.py", line 58, in load 2023-11-13T15:01:02.807691269Z return self.load_wsgiapp() 2023-11-13T15:01:02.807694769Z ^^^^^^^^^^^^^^^^^^^ 2023-11-13T15:01:02.807698169Z File "/opt/python/3/lib/python3.11/site-packages/gunicorn/app/wsgiapp.py", line 48, in load_wsgiapp 2023-11-13T15:01:02.807701769Z return util.import_app(self.app_uri) 2023-11-13T15:01:02.807705169Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 2023-11-13T15:01:02.807708669Z File "/opt/python/3/lib/python3.11/site-packages/gunicorn/util.py", line 359, in import_app 2023-11-13T15:01:02.807712269Z mod = importlib.import_module(module) 2023-11-13T15:01:02.807715669Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 2023-11-13T15:01:02.807719069Z File "/opt/python/3/lib/python3.11/importlib/init.py", line 126, in import_module 2023-11-13T15:01:02.807777469Z return _bootstrap._gcd_import(name[level:], package, level) 2023-11-13T15:01:02.807786769Z ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ 2023-11-13T15:01:02.807790869Z File "", line 1204, in _gcd_import 2023-11-13T15:01:02.807794869Z File "", line 1176, in _find_and_load 2023-11-13T15:01:02.807798569Z File "", line 1140, in _find_and_load_unlocked 2023-11-13T15:01:02.807802169Z ModuleNotFoundError: No module named 'main' 2023-11-13T15:01:02.818257005Z [2023-11-13 15:01:02 +0000] [65] [INFO] Worker exiting (pid: 65) 2023-11-13T15:01:04.082955771Z [2023-11-13 15:01:04 +0000] [59] [INFO] Shutting down: Master 2023-11-13T15:01:04.112193770Z [2023-11-13 15:01:04 +0000] [59] [INFO] Reason: Worker failed to boot.

OS and Version?

Windows 11 Pro

azd version?

azd version 1.4.3 (commit d165bd2de96dae75de57604c0d8a5553ae214618)

logs deployment center

logs deployment center.txt

MarPeg53 avatar Nov 13 '23 15:11 MarPeg53

Sometimes that means the app is still starting up (the code isn't fully loaded), have you tried waiting 10 minutes and checking again?

pamelafox avatar Nov 13 '23 17:11 pamelafox

yes, I waited much longer than 10 minutes and it didn't help.

MarPeg53 avatar Nov 13 '23 18:11 MarPeg53

Okay, well the error indicates that it can't find main.py, which means something went awry with the code upload, since app/backend/ should have a main.py. You could try re-running "azd deploy", and/or you could check the Deployment logs in the Azure Portal to see if it reported any issues with deployment. See first part of my blog post here: https://blog.pamelafox.org/2023/06/tips-for-debugging-flask-deployments-to.html

pamelafox avatar Nov 13 '23 21:11 pamelafox

Thank you for your help Pamela. Re-running with azd deploy didn't help and the logs also look normal from my point of view? Could it be that it has to do with the changes in the backend and the imported modules, even though it works locally? Any problems with Linux on azure and Windows locally?

image

Command oryx build.txt

MarPeg53 avatar Nov 14 '23 12:11 MarPeg53

Hm, the Oryx build logs look fine.

Your logs look like what I see when the app starts to restart the server before it has the code fully ready. It errors, but then once the code is ready, the next server restart works. I wonder if you can try Restart Server or running just azd deploy.

I'll share the logs from my most recent server start, it looks like yours at first and then fixes itself.

2023-11-14T22:46:50.590985786Z    _____                               
2023-11-14T22:46:50.591034989Z   /  _  \ __________ _________   ____  
2023-11-14T22:46:50.591046990Z  /  /_\  \\___   /  |  \_  __ \_/ __ \ 
2023-11-14T22:46:50.591051890Z /    |    \/    /|  |  /|  | \/\  ___/ 
2023-11-14T22:46:50.591056091Z \____|__  /_____ \____/ |__|    \___  >
2023-11-14T22:46:50.591061391Z         \/      \/                  \/ 
2023-11-14T22:46:50.591065491Z A P P   S E R V I C E   O N   L I N U X
2023-11-14T22:46:50.591069391Z 
2023-11-14T22:46:50.591073192Z Documentation: http://aka.ms/webapp-linux
2023-11-14T22:46:50.591077092Z Python 3.11.4
2023-11-14T22:46:50.591080992Z Note: Any data outside '/home' is not persisted
2023-11-14T22:47:00.677725263Z Starting OpenBSD Secure Shell server: sshd.
2023-11-14T22:47:01.212757873Z Site's appCommandLine: python3 -m gunicorn main:app
2023-11-14T22:47:02.321658713Z Starting periodic command scheduler: cron.
2023-11-14T22:47:02.321691315Z Launching oryx with: create-script -appPath /home/site/wwwroot -output /opt/startup/startup.sh -virtualEnvName antenv -defaultApp /opt/defaultsite -userStartupCommand 'python3 -m gunicorn main:app'
2023-11-14T22:47:02.812998063Z Could not find build manifest file at '/home/site/wwwroot/oryx-manifest.toml'
2023-11-14T22:47:02.814704385Z Could not find operation ID in manifest. Generating an operation id...
2023-11-14T22:47:02.821619280Z Build Operation ID: c5688804-09b6-47b3-ad6f-355838c172f3
2023-11-14T22:47:03.795591343Z Oryx Version: 0.2.20230707.1, Commit: 0bd28e69919b5e8beba451e8677e3345f0be8361, ReleaseTagName: 20230707.1
2023-11-14T22:47:03.902461487Z Writing output script to '/opt/startup/startup.sh'
2023-11-14T22:47:04.066207297Z WARNING: Could not find virtual environment directory /home/site/wwwroot/antenv.
2023-11-14T22:47:04.066252400Z WARNING: Could not find package directory /home/site/wwwroot/__oryx_packages__.
2023-11-14T22:47:08.329477991Z [2023-11-14 22:47:08 +0000] [72] [INFO] Starting gunicorn 20.1.0
2023-11-14T22:47:08.338782656Z [2023-11-14 22:47:08 +0000] [72] [INFO] Listening at: http://0.0.0.0:8000 (72)
2023-11-14T22:47:08.338826059Z [2023-11-14 22:47:08 +0000] [72] [INFO] Using worker: sync
2023-11-14T22:47:08.416792928Z [2023-11-14 22:47:08 +0000] [73] [INFO] Booting worker with pid: 73
2023-11-14T22:47:08.682769626Z [2023-11-14 22:47:08 +0000] [73] [ERROR] Exception in worker process
2023-11-14T22:47:08.682839031Z Traceback (most recent call last):
2023-11-14T22:47:08.682846231Z   File "/opt/python/3/lib/python3.11/site-packages/gunicorn/arbiter.py", line 589, in spawn_worker
2023-11-14T22:47:08.682852531Z     worker.init_process()
2023-11-14T22:47:08.682857532Z   File "/opt/python/3/lib/python3.11/site-packages/gunicorn/workers/base.py", line 134, in init_process
2023-11-14T22:47:08.682862732Z     self.load_wsgi()
2023-11-14T22:47:08.682885634Z   File "/opt/python/3/lib/python3.11/site-packages/gunicorn/workers/base.py", line 146, in load_wsgi
2023-11-14T22:47:08.682891134Z     self.wsgi = self.app.wsgi()
2023-11-14T22:47:08.682895735Z                 ^^^^^^^^^^^^^^^
2023-11-14T22:47:08.682900435Z   File "/opt/python/3/lib/python3.11/site-packages/gunicorn/app/base.py", line 67, in wsgi
2023-11-14T22:47:08.682905235Z     self.callable = self.load()
2023-11-14T22:47:08.682909836Z                     ^^^^^^^^^^^
2023-11-14T22:47:08.682914536Z   File "/opt/python/3/lib/python3.11/site-packages/gunicorn/app/wsgiapp.py", line 58, in load
2023-11-14T22:47:08.682919636Z     return self.load_wsgiapp()
2023-11-14T22:47:08.682924337Z            ^^^^^^^^^^^^^^^^^^^
2023-11-14T22:47:08.682928937Z   File "/opt/python/3/lib/python3.11/site-packages/gunicorn/app/wsgiapp.py", line 48, in load_wsgiapp
2023-11-14T22:47:08.682933637Z     return util.import_app(self.app_uri)
2023-11-14T22:47:08.682938238Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-14T22:47:08.682942838Z   File "/opt/python/3/lib/python3.11/site-packages/gunicorn/util.py", line 359, in import_app
2023-11-14T22:47:08.682947738Z     mod = importlib.import_module(module)
2023-11-14T22:47:08.682952239Z           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-14T22:47:08.682956839Z   File "/opt/python/3/lib/python3.11/importlib/__init__.py", line 126, in import_module
2023-11-14T22:47:08.682961539Z     return _bootstrap._gcd_import(name[level:], package, level)
2023-11-14T22:47:08.682966240Z            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2023-11-14T22:47:08.682971240Z   File "<frozen importlib._bootstrap>", line 1204, in _gcd_import
2023-11-14T22:47:08.682976540Z   File "<frozen importlib._bootstrap>", line 1176, in _find_and_load
2023-11-14T22:47:08.682981541Z   File "<frozen importlib._bootstrap>", line 1140, in _find_and_load_unlocked
2023-11-14T22:47:08.682986341Z ModuleNotFoundError: No module named 'main'
2023-11-14T22:47:08.691051117Z [2023-11-14 22:47:08 +0000] [73] [INFO] Worker exiting (pid: 73)
2023-11-14T22:47:09.443242935Z [2023-11-14 22:47:09 +0000] [72] [INFO] Shutting down: Master
2023-11-14T22:47:09.444523826Z [2023-11-14 22:47:09 +0000] [72] [INFO] Reason: Worker failed to boot.

2023-11-14T22:52:03.964739739Z    _____                               
2023-11-14T22:52:03.964788142Z   /  _  \ __________ _________   ____  
2023-11-14T22:52:03.964793742Z  /  /_\  \\___   /  |  \_  __ \_/ __ \ 
2023-11-14T22:52:03.964798242Z /    |    \/    /|  |  /|  | \/\  ___/ 
2023-11-14T22:52:03.964802542Z \____|__  /_____ \____/ |__|    \___  >
2023-11-14T22:52:03.964806943Z         \/      \/                  \/ 
2023-11-14T22:52:03.964811243Z A P P   S E R V I C E   O N   L I N U X
2023-11-14T22:52:03.964815343Z 
2023-11-14T22:52:03.964819243Z Documentation: http://aka.ms/webapp-linux
2023-11-14T22:52:03.964823343Z Python 3.11.4
2023-11-14T22:52:03.964827344Z Note: Any data outside '/home' is not persisted
2023-11-14T22:52:06.786887176Z Starting OpenBSD Secure Shell server: sshd.
2023-11-14T22:52:07.416817170Z Site's appCommandLine: python3 -m gunicorn main:app
2023-11-14T22:52:08.266259617Z Starting periodic command scheduler: cron.
2023-11-14T22:52:08.267829604Z Launching oryx with: create-script -appPath /home/site/wwwroot -output /opt/startup/startup.sh -virtualEnvName antenv -defaultApp /opt/defaultsite -userStartupCommand 'python3 -m gunicorn main:app'
2023-11-14T22:52:08.383778325Z Found build manifest file at '/home/site/wwwroot/oryx-manifest.toml'. Deserializing it...
2023-11-14T22:52:08.386990003Z Build Operation ID: 1cfa1d0420698611
2023-11-14T22:52:08.388924710Z Oryx Version: 0.2.20230707.1, Commit: 0bd28e69919b5e8beba451e8677e3345f0be8361, ReleaseTagName: 20230707.1
2023-11-14T22:52:08.394796935Z Output is compressed. Extracting it...
2023-11-14T22:52:08.495341403Z Extracting '/home/site/wwwroot/output.tar.gz' to directory '/tmp/8dbe562e63641aa'...
2023-11-14T22:52:38.954832207Z App path is set to '/tmp/8dbe562e63641aa'
2023-11-14T22:52:39.082043924Z Writing output script to '/opt/startup/startup.sh'
2023-11-14T22:52:39.212233861Z Using packages from virtual environment antenv located at /tmp/8dbe562e63641aa/antenv.
2023-11-14T22:52:39.212274963Z Updated PYTHONPATH to '/opt/startup/app_logs:/tmp/8dbe562e63641aa/antenv/lib/python3.11/site-packages'
2023-11-14T22:52:41.003229677Z [2023-11-14 22:52:41 +0000] [74] [INFO] Starting gunicorn 20.1.0
2023-11-14T22:52:41.005456895Z [2023-11-14 22:52:41 +0000] [74] [INFO] Listening at: http://0.0.0.0:8000 (74)
2023-11-14T22:52:41.011535719Z [2023-11-14 22:52:41 +0000] [74] [INFO] Using worker: uvicorn.workers.UvicornWorker
2023-11-14T22:52:41.033938612Z [2023-11-14 22:52:41 +0000] [75] [INFO] Booting worker with pid: 75
2023-11-14T22:52:41.102637171Z [2023-11-14 22:52:41 +0000] [76] [INFO] Booting worker with pid: 76
2023-11-14T22:52:41.163480212Z [2023-11-14 22:52:41 +0000] [77] [INFO] Booting worker with pid: 77
2023-11-14T22:53:13.740452991Z [2023-11-14 22:53:13 +0000] [76] [INFO] Started server process [76]
2023-11-14T22:53:13.741783053Z [2023-11-14 22:53:13 +0000] [76] [INFO] Waiting for application startup.
2023-11-14T22:53:13.751407099Z [2023-11-14 22:53:13 +0000] [75] [INFO] Started server process [75]
2023-11-14T22:53:13.752934270Z [2023-11-14 22:53:13 +0000] [75] [INFO] Waiting for application startup.
2023-11-14T22:53:13.761449965Z WARNING:azure.identity.aio._credentials.environment:Incomplete environment configuration. These variables are set: AZURE_TENANT_ID
2023-11-14T22:53:13.770482684Z WARNING:azure.identity.aio._credentials.environment:Incomplete environment configuration. These variables are set: AZURE_TENANT_ID
2023-11-14T22:53:13.780911967Z [2023-11-14 22:53:13 +0000] [77] [INFO] Started server process [77]
2023-11-14T22:53:13.790122794Z [2023-11-14 22:53:13 +0000] [77] [INFO] Waiting for application startup.
2023-11-14T22:53:13.793155135Z WARNING:azure.identity.aio._credentials.environment:Incomplete environment configuration. These variables are set: AZURE_TENANT_ID
2023-11-14T22:53:17.705159396Z [2023-11-14 22:53:17 +0000] [76] [INFO] Application startup complete.
2023-11-14T22:53:17.714583598Z [2023-11-14 22:53:17 +0000] [75] [INFO] Application startup complete.
2023-11-14T22:53:17.736555867Z [2023-11-14 22:53:17 +0000] [77] [INFO] Application startup complete.

pamelafox avatar Nov 15 '23 06:11 pamelafox

Rerunning server or deploy again results always in the same error. Do you have any other ideas about what could be the reason?

MarPeg53 avatar Nov 15 '23 12:11 MarPeg53

@MarPeg53 Are you able to SSH into the server from the Portal? If you can, then you can poke around and see what files are actually there. If you can't SSH due to the issue with starting the server, you could temporarily override the startup command to something that should always work (an empty string might work), and then SSH.

pamelafox avatar Nov 21 '23 00:11 pamelafox

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this issue will be closed.

github-actions[bot] avatar Jan 22 '24 01:01 github-actions[bot]

The app was just running fine, then suddenly I got an application error. I am getting the same error log:

2023-11-14T22:47:08.682971240Z File "", line 1204, in _gcd_import 2023-11-14T22:47:08.682976540Z File "", line 1176, in _find_and_load 2023-11-14T22:47:08.682981541Z File "", line 1140, in _find_and_load_unlocked 2023-11-14T22:47:08.682986341Z ModuleNotFoundError: No module named 'main' 2023-11-14T22:47:08.691051117Z [2023-11-14 22:47:08 +0000] [73] [INFO] Worker exiting (pid: 73) 2023-11-14T22:47:09.443242935Z [2023-11-14 22:47:09 +0000] [72] [INFO] Shutting down: Master 2023-11-14T22:47:09.444523826Z [2023-11-14 22:47:09 +0000] [72] [INFO] Reason: Worker failed to boot.

Did anyone find a solution to this?

chazarabriseis avatar Jan 30 '24 18:01 chazarabriseis

The error "No module named 'main'" generally means that the App Service does not have your application code (it cannot find main.py, which should be in the backend folder that gets uploaded). It's very common for that to be the case a few minutes after deploy while the server is still warming up. However, if you still see it, then I recommend checking the Deployment logs to make sure your last deployment was successful. You may need to do another deployment if the last one failed.

More details in my post at https://blog.pamelafox.org/2023/06/tips-for-debugging-flask-deployments-to.html

pamelafox avatar Jan 30 '24 19:01 pamelafox

@pamelafox checking the deployment logs was a great hint! Thank you! I reversed the last changes and now it works again. Need to check what went wrong there...

chazarabriseis avatar Jan 31 '24 08:01 chazarabriseis