calpoly-csai / api

Official API for the NIMBUS Voice Assistant accessible via HTTP REST protocol.
https://nimbus.api.calpolycsai.com/
GNU General Public License v3.0
9 stars 4 forks source link

heroku PermissionError: [Errno 13] '/usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info' #100

Closed mfekadu closed 4 years ago

mfekadu commented 4 years ago

only on heroku after, even after #99 merged,

See heroku logs

``` 2020-03-02T01:53:11.395759+00:00 heroku[web.1]: State changed from crashed to starting 2020-03-02T01:53:11.317426+00:00 app[web.1]: Traceback (most recent call last): 2020-03-02T01:53:11.317457+00:00 app[web.1]: File "/usr/local/bin/gunicorn", line 5, in 2020-03-02T01:53:11.317457+00:00 app[web.1]: from gunicorn.app.wsgiapp import run 2020-03-02T01:53:11.317461+00:00 app[web.1]: File "/usr/local/lib/python3.6/dist-packages/gunicorn/app/wsgiapp.py", line 9, in 2020-03-02T01:53:11.317461+00:00 app[web.1]: from gunicorn.app.base import Application 2020-03-02T01:53:11.317461+00:00 app[web.1]: File "/usr/local/lib/python3.6/dist-packages/gunicorn/app/base.py", line 11, in 2020-03-02T01:53:11.317465+00:00 app[web.1]: from gunicorn import util 2020-03-02T01:53:11.317465+00:00 app[web.1]: File "/usr/local/lib/python3.6/dist-packages/gunicorn/util.py", line 26, in 2020-03-02T01:53:11.317465+00:00 app[web.1]: import pkg_resources 2020-03-02T01:53:11.317465+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3088, in 2020-03-02T01:53:11.317466+00:00 app[web.1]: @_call_aside 2020-03-02T01:53:11.317466+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3072, in _call_aside 2020-03-02T01:53:11.317466+00:00 app[web.1]: f(*args, **kwargs) 2020-03-02T01:53:11.317472+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3101, in _initialize_master_working_set 2020-03-02T01:53:11.317472+00:00 app[web.1]: working_set = WorkingSet._build_master() 2020-03-02T01:53:11.317472+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 565, in _build_master 2020-03-02T01:53:11.317476+00:00 app[web.1]: ws = cls() 2020-03-02T01:53:11.317476+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 558, in __init__ 2020-03-02T01:53:11.317476+00:00 app[web.1]: self.add_entry(entry) 2020-03-02T01:53:11.317476+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 614, in add_entry 2020-03-02T01:53:11.317476+00:00 app[web.1]: for dist in find_distributions(entry, True): 2020-03-02T01:53:11.317476+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1964, in find_on_path 2020-03-02T01:53:11.317477+00:00 app[web.1]: for dist in factory(fullpath): 2020-03-02T01:53:11.317477+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2034, in distributions_from_metadata 2020-03-02T01:53:11.317477+00:00 app[web.1]: root, entry, metadata, precedence=DEVELOP_DIST, 2020-03-02T01:53:11.317477+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2473, in from_location 2020-03-02T01:53:11.317477+00:00 app[web.1]: py_version=py_version, platform=platform, **kw 2020-03-02T01:53:11.317477+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2835, in _reload_version 2020-03-02T01:53:11.317483+00:00 app[web.1]: md_version = _version_from_file(self._get_metadata(self.PKG_INFO)) 2020-03-02T01:53:11.317483+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2437, in _version_from_file 2020-03-02T01:53:11.317484+00:00 app[web.1]: line = next(iter(version_lines), '') 2020-03-02T01:53:11.317484+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2627, in _get_metadata 2020-03-02T01:53:11.317484+00:00 app[web.1]: for line in self.get_metadata_lines(name): 2020-03-02T01:53:11.317484+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1810, in get_metadata_lines 2020-03-02T01:53:11.317484+00:00 app[web.1]: return yield_lines(self.get_metadata(name)) 2020-03-02T01:53:11.317484+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1796, in get_metadata 2020-03-02T01:53:11.317484+00:00 app[web.1]: with io.open(self.path, encoding='utf-8', errors="replace") as f: 2020-03-02T01:53:11.317485+00:00 app[web.1]: PermissionError: [Errno 13] Permission denied: '/usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info' 2020-03-02T01:53:11.374772+00:00 heroku[web.1]: Process exited with status 1 ```

workaround

I ran this within the heroku run bash shell but my local docker container does not need this to be set... why?

chmod 777 /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info

Subsequently within the heroku run bash shell, I ran

./run.sh

And I no longer experienced the PermissionError and the flask_api was running within that shell

heroku ubuntu version

~ $ cat /etc/os-release
NAME="Ubuntu"
VERSION="18.04.4 LTS (Bionic Beaver)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 18.04.4 LTS"
VERSION_ID="18.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=bionic
UBUNTU_CODENAME=bionic
~ $ uname -r
4.4.0-1062-aws
~ $ python --version
Python 3.6.9
~ $ 
mfekadu commented 4 years ago

my local docker ubuntu version

# cat /etc/os-release
NAME="Ubuntu"
VERSION="18.04.4 LTS (Bionic Beaver)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 18.04.4 LTS"
VERSION_ID="18.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=bionic
UBUNTU_CODENAME=bionic
# uname -r
4.19.76-linuxkit
# python --version
Python 3.6.9
mfekadu commented 4 years ago

hopefully resolved by https://github.com/calpoly-csai/api/commit/dfbb567294de7b4697069b0bf95cd81dfff84876

even if the workflow passes/fails even if there remains weird permission issues within heroku

source .export_env_vars
./heroku_deploy.sh

^ this should re-deploy nicely

mfekadu commented 4 years ago

The permission issues were resolved and then https://github.com/calpoly-csai/api/commit/dc5076de3b3385238c5370907e145bbe8faca4c0 resolved some nltk download issues

just kidding.... 😢

See heroku logs

``` 2020-03-02T04:46:03.763742+00:00 heroku[web.1]: Starting process with command `gunicorn flask_api:app --config\=gunicorn_config.py` 2020-03-02T04:46:05.966651+00:00 heroku[web.1]: State changed from starting to crashed 2020-03-02T04:46:05.894258+00:00 app[web.1]: Traceback (most recent call last): 2020-03-02T04:46:05.894276+00:00 app[web.1]: File "/usr/local/bin/gunicorn", line 5, in 2020-03-02T04:46:05.894276+00:00 app[web.1]: from gunicorn.app.wsgiapp import run 2020-03-02T04:46:05.894277+00:00 app[web.1]: File "/usr/local/lib/python3.6/dist-packages/gunicorn/app/wsgiapp.py", line 9, in 2020-03-02T04:46:05.894277+00:00 app[web.1]: from gunicorn.app.base import Application 2020-03-02T04:46:05.894277+00:00 app[web.1]: File "/usr/local/lib/python3.6/dist-packages/gunicorn/app/base.py", line 11, in 2020-03-02T04:46:05.894278+00:00 app[web.1]: from gunicorn import util 2020-03-02T04:46:05.894278+00:00 app[web.1]: File "/usr/local/lib/python3.6/dist-packages/gunicorn/util.py", line 26, in 2020-03-02T04:46:05.894278+00:00 app[web.1]: import pkg_resources 2020-03-02T04:46:05.894279+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3088, in 2020-03-02T04:46:05.894279+00:00 app[web.1]: @_call_aside 2020-03-02T04:46:05.894279+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3072, in _call_aside 2020-03-02T04:46:05.894280+00:00 app[web.1]: f(*args, **kwargs) 2020-03-02T04:46:05.894281+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3101, in _initialize_master_working_set 2020-03-02T04:46:05.894281+00:00 app[web.1]: working_set = WorkingSet._build_master() 2020-03-02T04:46:05.894281+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 565, in _build_master 2020-03-02T04:46:05.894282+00:00 app[web.1]: ws = cls() 2020-03-02T04:46:05.894282+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 558, in __init__ 2020-03-02T04:46:05.894283+00:00 app[web.1]: self.add_entry(entry) 2020-03-02T04:46:05.894283+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 614, in add_entry 2020-03-02T04:46:05.894283+00:00 app[web.1]: for dist in find_distributions(entry, True): 2020-03-02T04:46:05.894284+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1964, in find_on_path 2020-03-02T04:46:05.894284+00:00 app[web.1]: for dist in factory(fullpath): 2020-03-02T04:46:05.894284+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2034, in distributions_from_metadata 2020-03-02T04:46:05.894284+00:00 app[web.1]: root, entry, metadata, precedence=DEVELOP_DIST, 2020-03-02T04:46:05.894285+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2473, in from_location 2020-03-02T04:46:05.894285+00:00 app[web.1]: py_version=py_version, platform=platform, **kw 2020-03-02T04:46:05.894286+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2835, in _reload_version 2020-03-02T04:46:05.894286+00:00 app[web.1]: md_version = _version_from_file(self._get_metadata(self.PKG_INFO)) 2020-03-02T04:46:05.894286+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2437, in _version_from_file 2020-03-02T04:46:05.894287+00:00 app[web.1]: line = next(iter(version_lines), '') 2020-03-02T04:46:05.894287+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2627, in _get_metadata 2020-03-02T04:46:05.894287+00:00 app[web.1]: for line in self.get_metadata_lines(name): 2020-03-02T04:46:05.894288+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1810, in get_metadata_lines 2020-03-02T04:46:05.894288+00:00 app[web.1]: return yield_lines(self.get_metadata(name)) 2020-03-02T04:46:05.894288+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1796, in get_metadata 2020-03-02T04:46:05.894289+00:00 app[web.1]: with io.open(self.path, encoding='utf-8', errors="replace") as f: 2020-03-02T04:46:05.894289+00:00 app[web.1]: PermissionError: [Errno 13] Permission denied: '/usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info' 2020-03-02T04:46:05.949239+00:00 heroku[web.1]: Process exited with status 1 ```

mfekadu commented 4 years ago

so ls -lah on the file with PermissionError shows that it literally has no permissions... weird

➜  ~ heroku run --app calpoly-csai-nimbus "ls -lah /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info"
Running ls -lah /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info on ⬢ calpoly-csai-nimbus... up, run.6735 (Standard-1X)
---------- 1 u40264 dyno 0 Mar  2 04:43 /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
mfekadu commented 4 years ago

Here's what I learned

I can run bash on the heroku dyno like this

➜  api git:(dev) heroku run --app calpoly-csai-nimbus "bash"
Running bash on ⬢ calpoly-csai-nimbus... up, run.8225 (Standard-1X)

which lets me inspect && temporarily change permissions of files (changes do not affect dyno running in production)

~ $ ls -lah /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
---------- 1 u4283 dyno 0 Mar  2 04:43 /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
~ $ chmod +rwx /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
~ $ ls -lah /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
-rwx------ 1 u4283 dyno 0 Mar  2 04:43 /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info

furthermore I can run but not access via postman the gunicorn executable

that's fine... it still lets me experiment with errors

See heroku logs

``` bash ~ $ gunicorn flask_api:app --config\=gunicorn_config.py Traceback (most recent call last): File "/usr/local/bin/gunicorn", line 5, in from gunicorn.app.wsgiapp import run File "/usr/local/lib/python3.6/dist-packages/gunicorn/app/wsgiapp.py", line 9, in from gunicorn.app.base import Application File "/usr/local/lib/python3.6/dist-packages/gunicorn/app/base.py", line 11, in from gunicorn import util File "/usr/local/lib/python3.6/dist-packages/gunicorn/util.py", line 26, in import pkg_resources File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3088, in @_call_aside File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3072, in _call_aside f(*args, **kwargs) File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3101, in _initialize_master_working_set working_set = WorkingSet._build_master() File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 565, in _build_master ws = cls() File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 558, in __init__ self.add_entry(entry) File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 614, in add_entry for dist in find_distributions(entry, True): File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1964, in find_on_path for dist in factory(fullpath): File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2034, in distributions_from_metadata root, entry, metadata, precedence=DEVELOP_DIST, File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2473, in from_location py_version=py_version, platform=platform, **kw File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2835, in _reload_version md_version = _version_from_file(self._get_metadata(self.PKG_INFO)) File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2437, in _version_from_file line = next(iter(version_lines), '') File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2627, in _get_metadata for line in self.get_metadata_lines(name): File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1810, in get_metadata_lines return yield_lines(self.get_metadata(name)) File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1796, in get_metadata with io.open(self.path, encoding='utf-8', errors="replace") as f: PermissionError: [Errno 13] Permission denied: '/usr/lib/python3/dist-packages/.wh.idna-2.6.egg-info' ```

I spent a good 10 minutes trying to set permissions on /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info

because ..wh.six-1.11.0.. was the cause of the original bug

~ $ ls -lah /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
-rwx------ 1 u4283 dyno 0 Mar  2 04:43 /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
~ $ chmod 755 /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
~ $ ls -lah /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
-rwxr-xr-x 1 u4283 dyno 0 Mar  2 04:43 /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info

but the issue is with another file

See heroku logs

``` bash ~ $ gunicorn flask_api:app --config\=gunicorn_config.py Traceback (most recent call last): File "/usr/local/bin/gunicorn", line 5, in from gunicorn.app.wsgiapp import run File "/usr/local/lib/python3.6/dist-packages/gunicorn/app/wsgiapp.py", line 9, in from gunicorn.app.base import Application File "/usr/local/lib/python3.6/dist-packages/gunicorn/app/base.py", line 11, in from gunicorn import util File "/usr/local/lib/python3.6/dist-packages/gunicorn/util.py", line 26, in import pkg_resources File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3088, in @_call_aside File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3072, in _call_aside f(*args, **kwargs) File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3101, in _initialize_master_working_set working_set = WorkingSet._build_master() File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 565, in _build_master ws = cls() File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 558, in __init__ self.add_entry(entry) File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 614, in add_entry for dist in find_distributions(entry, True): File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1964, in find_on_path for dist in factory(fullpath): File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2034, in distributions_from_metadata root, entry, metadata, precedence=DEVELOP_DIST, File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2473, in from_location py_version=py_version, platform=platform, **kw File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2835, in _reload_version md_version = _version_from_file(self._get_metadata(self.PKG_INFO)) File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2437, in _version_from_file line = next(iter(version_lines), '') File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2627, in _get_metadata for line in self.get_metadata_lines(name): File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1810, in get_metadata_lines return yield_lines(self.get_metadata(name)) File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1796, in get_metadata with io.open(self.path, encoding='utf-8', errors="replace") as f: PermissionError: [Errno 13] Permission denied: '/usr/lib/python3/dist-packages/.wh.idna-2.6.egg-info' ```

all these permissions meant nothing

~ $ ls -lah /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
-rwxr-xr-x 1 u4283 dyno 0 Mar  2 04:43 /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info

finally changing permissions on wh.idna-2.6.egg-info was the fix in this experiment

See heroku logs

``` bash ~ $ chmod +rwx /usr/lib/python3/dist-packages/.wh.idna-2.6.egg-info ~ $ gunicorn flask_api:app --config\=gunicorn_config.py [2020-03-02 05:25:22 +0000] [16] [INFO] Starting gunicorn 20.0.4 [2020-03-02 05:25:22 +0000] [16] [INFO] Listening at: http://0.0.0.0:32229 (16) [2020-03-02 05:25:22 +0000] [16] [INFO] Using worker: sync [2020-03-02 05:25:22 +0000] [19] [INFO] Booting worker with pid: 19 [2020-03-02 05:25:22 +0000] [20] [INFO] Booting worker with pid: 20 [2020-03-02 05:25:22 +0000] [22] [INFO] Booting worker with pid: 22 initialized database session initialized NimbusMySQLAlchemy initialized database session initialized NimbusMySQLAlchemy initialized database session initialized NimbusMySQLAlchemy ^C[2020-03-02 05:26:13 +0000] [16] [INFO] Handling signal: int [2020-03-02 05:26:13 +0000] [19] [INFO] Worker exiting (pid: 19) [2020-03-02 05:26:13 +0000] [20] [INFO] Worker exiting (pid: 20) [2020-03-02 05:26:13 +0000] [22] [INFO] Worker exiting (pid: 22) NimbusMySQLAlchemy closed NimbusMySQLAlchemy closed NimbusMySQLAlchemy closed [2020-03-02 05:26:13 +0000] [16] [INFO] Shutting down: Master ```

hmm... maybe I could just chmod +rwx /usr/lib/python3/dist-packages/.wh* within the Dockerfile to catch all possible wheel-egg-info-file-things

~ $ ls -lah /usr/lib/python3/dist-packages/.wh*
---------- 1 u4283 dyno 0 Mar  2 04:43 /usr/lib/python3/dist-packages/.wh.idna
-rwx------ 1 u4283 dyno 0 Mar  2 04:43 /usr/lib/python3/dist-packages/.wh.idna-2.6.egg-info
-rwxr-xr-x 1 u4283 dyno 0 Mar  2 04:43 /usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info
---------- 1 u4283 dyno 0 Mar  2 04:43 /usr/lib/python3/dist-packages/.wh.six.py
~ $
mfekadu commented 4 years ago

The commit 1d9c805 did not resolve this issue

in fact the deployment failed

it makes no sense since, we just saw those files

Pasted_Image_3_1_20__9_48_PM

What I still don't understand is why the deployment workflow through GitHub Workflows contains those files without the right permissions set.

However, effectively the same workflow, through the simple ./heroku_deploy.sh executed from my macOS Catalina 10.15, works fine and even does not include those .wh...info files.

$ heroku --version
heroku/7.38.0 darwin-x64 node-v12.13.0
mfekadu commented 4 years ago

even after the most insecure commit 122ff4d the permissions are not properly set

See Heroku Logs

``` ➜ api git:(dev) heroku logs --app calpoly-csai-nimbus 2020-03-02T05:57:19.261998+00:00 heroku[web.1]: State changed from crashed to starting 2020-03-02T05:57:36.801160+00:00 heroku[web.1]: Starting process with command `gunicorn flask_api:app --config\=gunicorn_config.py` 2020-03-02T05:57:38.692818+00:00 heroku[web.1]: State changed from starting to crashed 2020-03-02T05:57:38.697131+00:00 heroku[web.1]: State changed from crashed to starting 2020-03-02T05:57:38.601411+00:00 app[web.1]: Traceback (most recent call last): 2020-03-02T05:57:38.601423+00:00 app[web.1]: File "/usr/local/bin/gunicorn", line 5, in 2020-03-02T05:57:38.601424+00:00 app[web.1]: from gunicorn.app.wsgiapp import run 2020-03-02T05:57:38.601424+00:00 app[web.1]: File "/usr/local/lib/python3.6/dist-packages/gunicorn/app/wsgiapp.py", line 9, in 2020-03-02T05:57:38.601425+00:00 app[web.1]: from gunicorn.app.base import Application 2020-03-02T05:57:38.601425+00:00 app[web.1]: File "/usr/local/lib/python3.6/dist-packages/gunicorn/app/base.py", line 11, in 2020-03-02T05:57:38.601426+00:00 app[web.1]: from gunicorn import util 2020-03-02T05:57:38.601426+00:00 app[web.1]: File "/usr/local/lib/python3.6/dist-packages/gunicorn/util.py", line 26, in 2020-03-02T05:57:38.601426+00:00 app[web.1]: import pkg_resources 2020-03-02T05:57:38.601427+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3088, in 2020-03-02T05:57:38.601427+00:00 app[web.1]: @_call_aside 2020-03-02T05:57:38.601427+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3072, in _call_aside 2020-03-02T05:57:38.601428+00:00 app[web.1]: f(*args, **kwargs) 2020-03-02T05:57:38.601428+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 3101, in _initialize_master_working_set 2020-03-02T05:57:38.601429+00:00 app[web.1]: working_set = WorkingSet._build_master() 2020-03-02T05:57:38.601429+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 565, in _build_master 2020-03-02T05:57:38.601429+00:00 app[web.1]: ws = cls() 2020-03-02T05:57:38.601430+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 558, in __init__ 2020-03-02T05:57:38.601430+00:00 app[web.1]: self.add_entry(entry) 2020-03-02T05:57:38.601431+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 614, in add_entry 2020-03-02T05:57:38.601431+00:00 app[web.1]: for dist in find_distributions(entry, True): 2020-03-02T05:57:38.601431+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1964, in find_on_path 2020-03-02T05:57:38.601436+00:00 app[web.1]: for dist in factory(fullpath): 2020-03-02T05:57:38.601436+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2034, in distributions_from_metadata 2020-03-02T05:57:38.601437+00:00 app[web.1]: root, entry, metadata, precedence=DEVELOP_DIST, 2020-03-02T05:57:38.601437+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2473, in from_location 2020-03-02T05:57:38.601438+00:00 app[web.1]: py_version=py_version, platform=platform, **kw 2020-03-02T05:57:38.601438+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2835, in _reload_version 2020-03-02T05:57:38.601438+00:00 app[web.1]: md_version = _version_from_file(self._get_metadata(self.PKG_INFO)) 2020-03-02T05:57:38.601439+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2437, in _version_from_file 2020-03-02T05:57:38.601439+00:00 app[web.1]: line = next(iter(version_lines), '') 2020-03-02T05:57:38.601439+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 2627, in _get_metadata 2020-03-02T05:57:38.601440+00:00 app[web.1]: for line in self.get_metadata_lines(name): 2020-03-02T05:57:38.601440+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1810, in get_metadata_lines 2020-03-02T05:57:38.601441+00:00 app[web.1]: return yield_lines(self.get_metadata(name)) 2020-03-02T05:57:38.601441+00:00 app[web.1]: File "/usr/lib/python3/dist-packages/pkg_resources/__init__.py", line 1796, in get_metadata 2020-03-02T05:57:38.601442+00:00 app[web.1]: with io.open(self.path, encoding='utf-8', errors="replace") as f: 2020-03-02T05:57:38.601442+00:00 app[web.1]: PermissionError: [Errno 13] Permission denied: '/usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info' 2020-03-02T05:57:38.676188+00:00 heroku[web.1]: Process exited with status 1 ➜ api git:(dev)➜ api git:(dev) ```

mfekadu commented 4 years ago

amazing... there was no affect at all by chmod on any of the files

maybe I need to sudo?

perhaps this issue has something to do with docker layers?

See heroku logs

``` ➜ api git:(dev) heroku run --app calpoly-csai-nimbus "ls -lah /usr/lib/python3/dist-packages/" Running ls -lah /usr/lib/python3/dist-packages/ on ⬢ calpoly-csai-nimbus... up, run.5763 (Standard-1X) total 508K drwx------ 1 u11199 dyno 4.0K Mar 2 05:55 . drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 .. ---------- 1 u11199 dyno 0 Mar 2 05:55 .wh.idna ---------- 1 u11199 dyno 0 Mar 2 05:55 .wh.idna-2.6.egg-info ---------- 1 u11199 dyno 0 Mar 2 05:55 .wh.six-1.11.0.egg-info ---------- 1 u11199 dyno 0 Mar 2 05:55 .wh.six.py drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 Crypto -rwx------ 1 u11199 dyno 119 Nov 7 10:44 README.txt drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 SecretStorage-2.3.1.egg-info drwx------ 1 u11199 dyno 4.0K Mar 2 05:55 __pycache__ -rwx------ 1 u11199 dyno 166K Feb 27 2018 _cffi_backend.cpython-36m-x86_64-linux-gnu.so -rwx------ 1 u11199 dyno 156K Jan 29 2018 _dbus_bindings.cpython-36m-x86_64-linux-gnu.so -rwx------ 1 u11199 dyno 19K Jan 29 2018 _dbus_glib_bindings.cpython-36m-x86_64-linux-gnu.so drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 asn1crypto drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 asn1crypto-0.24.0.egg-info drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 cryptography drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 cryptography-2.1.4.egg-info drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 dbus -rwx------ 1 u11199 dyno 126 Mar 18 2018 easy_install.py drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 gi drwx------ 3 u11199 dyno 4.0K Mar 2 05:54 idna drwx------ 2 u11199 dyno 4.0K Mar 2 05:54 idna-2.6.egg-info drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 keyring drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 keyring-10.6.0.egg-info drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 keyrings drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 keyrings.alt-3.0.egg-info drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 pip drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 pip-9.0.1.egg-info drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 pkg_resources -rwx------ 1 u11199 dyno 666 Apr 3 2018 pycrypto-2.6.1.egg-info -rwx------ 1 u11199 dyno 1013 Jan 29 2019 pygobject-3.26.1.egg-info drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 pygtkcompat -rwx------ 1 u11199 dyno 576 Apr 25 2018 pyxdg-0.25.egg-info drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 secretstorage drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 setuptools drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 setuptools-39.0.1.egg-info drwx------ 2 u11199 dyno 4.0K Mar 2 05:54 six-1.11.0.egg-info -rw------- 1 u11199 dyno 31K Sep 17 2017 six.py drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 wheel drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 wheel-0.30.0.egg-info drwx------ 1 u11199 dyno 4.0K Mar 2 05:54 xdg ➜ api git:(dev) ```

mfekadu commented 4 years ago

still bug, sad 😢

2020-03-02T06:23:22.812618+00:00 app[web.1]: PermissionError: [Errno 13] Permission denied: '/usr/lib/python3/dist-packages/.wh.six-1.11.0.egg-info'

chmod did nothing

See heroku logs

``` ➜ api git:(dev) ✗ heroku run --app calpoly-csai-nimbus "ls -lah /usr/lib/python3/dist-packages/" Running ls -lah /usr/lib/python3/dist-packages/ on ⬢ calpoly-csai-nimbus... up, run.9310 (Standard-1X) total 508K drwx------ 1 u12123 dyno 4.0K Mar 2 06:21 . drwx------ 1 u12123 dyno 4.0K Mar 2 06:19 .. ---------- 1 u12123 dyno 0 Mar 2 06:21 .wh.idna ---------- 1 u12123 dyno 0 Mar 2 06:21 .wh.idna-2.6.egg-info ---------- 1 u12123 dyno 0 Mar 2 06:21 .wh.six-1.11.0.egg-info ---------- 1 u12123 dyno 0 Mar 2 06:21 .wh.six.py drwx------ 11 u12123 dyno 4.0K Mar 2 06:20 Crypto -rwx------ 1 u12123 dyno 119 Nov 7 10:44 README.txt drwx------ 2 u12123 dyno 4.0K Mar 2 06:20 SecretStorage-2.3.1.egg-info drwx------ 1 u12123 dyno 4.0K Mar 2 06:21 __pycache__ -rwx------ 1 u12123 dyno 166K Feb 27 2018 _cffi_backend.cpython-36m-x86_64-linux-gnu.so -rwx------ 1 u12123 dyno 156K Jan 29 2018 _dbus_bindings.cpython-36m-x86_64-linux-gnu.so -rwx------ 1 u12123 dyno 19K Jan 29 2018 _dbus_glib_bindings.cpython-36m-x86_64-linux-gnu.so drwx------ 4 u12123 dyno 4.0K Mar 2 06:20 asn1crypto drwx------ 2 u12123 dyno 4.0K Mar 2 06:20 asn1crypto-0.24.0.egg-info drwx------ 5 u12123 dyno 4.0K Mar 2 06:20 cryptography drwx------ 2 u12123 dyno 4.0K Mar 2 06:20 cryptography-2.1.4.egg-info drwx------ 4 u12123 dyno 4.0K Mar 2 06:20 dbus -rwx------ 1 u12123 dyno 126 Mar 18 2018 easy_install.py drwx------ 5 u12123 dyno 4.0K Mar 2 06:20 gi drwx------ 3 u12123 dyno 4.0K Mar 2 06:20 idna drwx------ 2 u12123 dyno 4.0K Mar 2 06:20 idna-2.6.egg-info drwx------ 6 u12123 dyno 4.0K Mar 2 06:20 keyring drwx------ 2 u12123 dyno 4.0K Mar 2 06:20 keyring-10.6.0.egg-info drwx------ 3 u12123 dyno 4.0K Mar 2 06:20 keyrings drwx------ 2 u12123 dyno 4.0K Mar 2 06:20 keyrings.alt-3.0.egg-info drwx------ 11 u12123 dyno 4.0K Mar 2 06:20 pip drwx------ 2 u12123 dyno 4.0K Mar 2 06:20 pip-9.0.1.egg-info drwx------ 5 u12123 dyno 4.0K Mar 2 06:20 pkg_resources -rwx------ 1 u12123 dyno 666 Apr 3 2018 pycrypto-2.6.1.egg-info -rwx------ 1 u12123 dyno 1013 Jan 29 2019 pygobject-3.26.1.egg-info drwx------ 3 u12123 dyno 4.0K Mar 2 06:20 pygtkcompat -rwx------ 1 u12123 dyno 576 Apr 25 2018 pyxdg-0.25.egg-info drwx------ 3 u12123 dyno 4.0K Mar 2 06:20 secretstorage drwx------ 6 u12123 dyno 4.0K Mar 2 06:20 setuptools drwx------ 2 u12123 dyno 4.0K Mar 2 06:20 setuptools-39.0.1.egg-info drwx------ 2 u12123 dyno 4.0K Mar 2 06:20 six-1.11.0.egg-info -rwx------ 1 u12123 dyno 31K Sep 17 2017 six.py drwx------ 5 u12123 dyno 4.0K Mar 2 06:20 wheel drwx------ 2 u12123 dyno 4.0K Mar 2 06:20 wheel-0.30.0.egg-info drwx------ 3 u12123 dyno 4.0K Mar 2 06:20 xdg ```

mfekadu commented 4 years ago

just noticed that idna and six both get uninstalled in favor of different versions of themselves

image image
mfekadu commented 4 years ago

new hypothesis: what if i specify specific versions of six and idna within requirements?

➜  api git:(dev) ✗ cat requirements.txt | grep -- 'six\|idna'
idna==2.9
six==1.13.0
➜  api git:(dev) ✗ heroku run --app calpoly-csai-nimbus "pip list | grep -- 'six\|idna'"
Running pip list | grep -- 'six\|idna' on ⬢ calpoly-csai-nimbus... up, run.4277 (Standard-1X)
.wh.idna                 2.6
.wh.six                  1.11.0
idna                     2.9
six                      1.13.0
mfekadu commented 4 years ago

so there is six

image image

idna

image image

the run went well

the heroku logs are good 😮 😄

$ heroku logs --app calpoly-csai-nimbus

2020-03-02T08:17:38.560491+00:00 heroku[web.1]: Starting process with command `gunicorn flask_api:app --config\=gunicorn_config.py`
2020-03-02T08:17:40.491868+00:00 app[web.1]: [2020-03-02 08:17:40 +0000] [5] [INFO] Starting gunicorn 20.0.4
2020-03-02T08:17:40.492507+00:00 app[web.1]: [2020-03-02 08:17:40 +0000] [5] [INFO] Listening at: http://0.0.0.0:21281 (5)
2020-03-02T08:17:40.492591+00:00 app[web.1]: [2020-03-02 08:17:40 +0000] [5] [INFO] Using worker: sync
2020-03-02T08:17:40.496508+00:00 app[web.1]: [2020-03-02 08:17:40 +0000] [8] [INFO] Booting worker with pid: 8
2020-03-02T08:17:40.580604+00:00 app[web.1]: [2020-03-02 08:17:40 +0000] [9] [INFO] Booting worker with pid: 9
2020-03-02T08:17:40.672712+00:00 app[web.1]: [2020-03-02 08:17:40 +0000] [11] [INFO] Booting worker with pid: 11
2020-03-02T08:17:41.192659+00:00 heroku[web.1]: State changed from starting to up

the permissions in that folder seem decent

$ heroku run --app calpoly-csai-nimbus "ls -lah /usr/lib/python3/dist-packages/"

Running ls -lah /usr/lib/python3/dist-packages/ on ⬢ calpoly-csai-nimbus... up, run.3036 (Standard-1X)
total 508K
drwx------ 28 u21594 dyno 4.0K Mar  2 08:14 .
drwx------  3 u21594 dyno 4.0K Mar  2 08:14 ..
drwx------ 11 u21594 dyno 4.0K Mar  2 08:14 Crypto
-rwx------  1 u21594 dyno  119 Nov  7 10:44 README.txt
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 SecretStorage-2.3.1.egg-info
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 __pycache__
-rwx------  1 u21594 dyno 166K Feb 27  2018 _cffi_backend.cpython-36m-x86_64-linux-gnu.so
-rwx------  1 u21594 dyno 156K Jan 29  2018 _dbus_bindings.cpython-36m-x86_64-linux-gnu.so
-rwx------  1 u21594 dyno  19K Jan 29  2018 _dbus_glib_bindings.cpython-36m-x86_64-linux-gnu.so
drwx------  4 u21594 dyno 4.0K Mar  2 08:14 asn1crypto
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 asn1crypto-0.24.0.egg-info
drwx------  5 u21594 dyno 4.0K Mar  2 08:14 cryptography
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 cryptography-2.1.4.egg-info
drwx------  4 u21594 dyno 4.0K Mar  2 08:14 dbus
-rwx------  1 u21594 dyno  126 Mar 18  2018 easy_install.py
drwx------  5 u21594 dyno 4.0K Mar  2 08:14 gi
drwx------  3 u21594 dyno 4.0K Mar  2 08:14 idna
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 idna-2.6.egg-info
drwx------  6 u21594 dyno 4.0K Mar  2 08:14 keyring
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 keyring-10.6.0.egg-info
drwx------  3 u21594 dyno 4.0K Mar  2 08:14 keyrings
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 keyrings.alt-3.0.egg-info
drwx------ 11 u21594 dyno 4.0K Mar  2 08:14 pip
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 pip-9.0.1.egg-info
drwx------  5 u21594 dyno 4.0K Mar  2 08:14 pkg_resources
-rwx------  1 u21594 dyno  666 Apr  3  2018 pycrypto-2.6.1.egg-info
-rwx------  1 u21594 dyno 1013 Jan 29  2019 pygobject-3.26.1.egg-info
drwx------  3 u21594 dyno 4.0K Mar  2 08:14 pygtkcompat
-rwx------  1 u21594 dyno  576 Apr 25  2018 pyxdg-0.25.egg-info
drwx------  3 u21594 dyno 4.0K Mar  2 08:14 secretstorage
drwx------  6 u21594 dyno 4.0K Mar  2 08:14 setuptools
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 setuptools-39.0.1.egg-info
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 six-1.11.0.egg-info
-rwx------  1 u21594 dyno  31K Sep 17  2017 six.py
drwx------  5 u21594 dyno 4.0K Mar  2 08:14 wheel
drwx------  2 u21594 dyno 4.0K Mar  2 08:14 wheel-0.30.0.egg-info
drwx------  3 u21594 dyno 4.0K Mar  2 08:14 xdg
(api) ➜  api git:(dev)

when I POST to the /ask endpoint I get an answer!

image

no errors within the logs upon sending POST request

$ heroku logs --app calpoly-csai-nimbus | tail -5

2020-03-02T08:22:01.539920+00:00 heroku[run.3036]: Awaiting client
2020-03-02T08:22:01.578367+00:00 heroku[run.3036]: Starting process with command `ls -lah /usr/lib/python3/dist-packages/`
2020-03-02T08:22:06.442733+00:00 heroku[run.3036]: State changed from up to complete
2020-03-02T08:22:06.425094+00:00 heroku[run.3036]: Process exited with status 0
2020-03-02T08:23:14.183990+00:00 heroku[router]: at=info method=POST path="/ask" host=calpoly-csai-nimbus.herokuapp.com request_id=4bb85afd-08d3-4353-a612-6702e826b380 fwd="129.65.145.159" dyno=web.1 connect=1ms service=5398ms status=200 bytes=255 protocol=https

another POST, a different answer, as expected

image

but this time we are hitting some memory limits

$ heroku logs --app calpoly-csai-nimbus | tail -5

2020-03-02T08:26:35.711772+00:00 heroku[router]: at=info method=POST path="/ask" host=calpoly-csai-nimbus.herokuapp.com request_id=6812b1d6-5268-4853-95e2-f1c1065cacf6 fwd="129.65.145.159" dyno=web.1 connect=1ms service=4127ms status=200 bytes=326 protocol=https
2020-03-02T08:26:42.011245+00:00 heroku[web.1]: Process running mem=530M(102.8%)
2020-03-02T08:26:42.011245+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)
2020-03-02T08:27:01.235802+00:00 heroku[web.1]: Process running mem=530M(102.8%)
2020-03-02T08:27:01.235802+00:00 heroku[web.1]: Error R14 (Memory quota exceeded)

performance issues are okay. At least now we can say 48336b0 definitely did fix the issue. Specifically by constraining the requirements idna==2.6 six==1.11.0

I found it helpful to use pipenv graph in order to make sure that I picked a version for both six and idna that satisfies all the other requirements.

Vrroom commented 4 years ago

Hi, thanks for documenting this. I was stuck with a similar problem for 3 days and your observations fixed it for me!