Python requests module issue

[Chris Barton]

Hello,

I've been working on the deployment of a Flask application using mod_wsgi4.5.18 (compiled against Python3.6.1) and have been encountering issues with the requests library that only seem to manifest when the Flask app is run from behind Apache & mod_wsgi. When the app is invoked from the virtualenv python interpreter it works flawlessly.

The problem occurs in areas where we are attempting to use the requests library to make a call to external APIs (BlueJeans & Slack) during the handling of a request to our Flask app. 

Here are some pieces of our current configuration. We've been puzzled by this for the past two weeks and do not seem to be getting any closer to a solution. At this point the development team is asking to look at other options such as Nginx & Gunicorn.

Python traceback:

[Fri Sep 22 16:35:49.378817 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515] [2017-09-22 16:35:49,377] ERROR in app: Exception on /conference [POST]

[Fri Sep 22 16:35:49.378844 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515] Traceback (most recent call last):

[Fri Sep 22 16:35:49.378847 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/rest_api_v1/util/bluejeans.py", line 13, in password_grant

[Fri Sep 22 16:35:49.378850 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     r = requests.post(BASE_URL + '/oauth2/token?Password', json=json)

[Fri Sep 22 16:35:49.378852 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515] AttributeError: module 'requests' has no attribute 'post'

[Fri Sep 22 16:35:49.378855 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]

[Fri Sep 22 16:35:49.378857 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515] During handling of the above exception, another exception occurred:

[Fri Sep 22 16:35:49.378859 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]

[Fri Sep 22 16:35:49.378861 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515] Traceback (most recent call last):

[Fri Sep 22 16:35:49.378863 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/app.py", line 1982, in wsgi_app

[Fri Sep 22 16:35:49.378866 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     response = self.full_dispatch_request()

[Fri Sep 22 16:35:49.378868 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/app.py", line 1614, in full_dispatch_request

[Fri Sep 22 16:35:49.378871 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     rv = self.handle_user_exception(e)

[Fri Sep 22 16:35:49.378873 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask_cors/extension.py", line 161, in wrapped_function

[Fri Sep 22 16:35:49.378875 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     return cors_after_request(app.make_response(f(*args, **kwargs)))

[Fri Sep 22 16:35:49.378877 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/app.py", line 1517, in handle_user_exception

[Fri Sep 22 16:35:49.378880 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     reraise(exc_type, exc_value, tb)

[Fri Sep 22 16:35:49.378882 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/_compat.py", line 33, in reraise

[Fri Sep 22 16:35:49.378884 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     raise value

[Fri Sep 22 16:35:49.378886 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/app.py", line 1612, in full_dispatch_request

[Fri Sep 22 16:35:49.378889 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     rv = self.dispatch_request()

[Fri Sep 22 16:35:49.378891 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/app.py", line 1598, in dispatch_request

[Fri Sep 22 16:35:49.378893 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     return self.view_functions[rule.endpoint](**req.view_args)

[Fri Sep 22 16:35:49.378895 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/rest_api_v1/endpoints/conference.py", line 11, in create_conference

[Fri Sep 22 16:35:49.378898 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     response, status = conference.create_conference(request.json)

[Fri Sep 22 16:35:49.378902 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/rest_api_v1/logic/conference.py", line 35, in create_conference

[Fri Sep 22 16:35:49.378904 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     userId, token = bjn_util.password_grant(bjn_config.USERNAME, bjn_config.PASSWORD)

[Fri Sep 22 16:35:49.378907 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/rest_api_v1/util/bluejeans.py", line 24, in password_grant

[Fri Sep 22 16:35:49.378909 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     logger.error(ex, application='Conference')

[Fri Sep 22 16:35:49.378911 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/rest_api_v1/util/logger.py", line 81, in error

[Fri Sep 22 16:35:49.378913 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     log(message, logType='error', application=application, traceback=traceback)

[Fri Sep 22 16:35:49.378916 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/rest_api_v1/util/logger.py", line 70, in log

[Fri Sep 22 16:35:49.378918 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     slack(message + '\\n' + traceback, 'https://hooks.slack.com/services/<URL REMOVED>')

[Fri Sep 22 16:35:49.378920 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]   File "/var/www/sites/api/rest_api_v1/util/logger.py", line 20, in slack

[Fri Sep 22 16:35:49.378923 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515]     response = requests.post(webhook_url, data=json.dumps(slack_data),

[Fri Sep 22 16:35:49.378926 2017] [wsgi:error] [pid 1708:tid 139626802534144] [remote 10.6.70.171:50515] AttributeError: module 'requests' has no attribute 'post'

Apache startup message showing mod_wsgi compiled for Python3.6:

[Wed Sep 27 16:13:25.690202 2017] [mpm_event:notice] [pid 63496:tid 139773643462528] AH00489: Apache/2.4.18 (Ubuntu) OpenSSL/1.0.2g mod_wsgi/4.5.18 Python/3.6 configured -- resuming normal operations

Python packages installed in the virtualenv:

(venv) root@ub50368:/var/www/sites/api# pip list

certifi (2017.7.27.1)

chardet (3.0.4)

click (6.7)

configparser (3.5.0)

Flask (0.12.2)

Flask-Cors (3.0.3)

Flask-MySQL (1.4.0)

idna (2.6)

itsdangerous (0.24)

Jinja2 (2.9.6)

MarkupSafe (1.0)

pip (9.0.1)

PyMySQL (0.7.11)

pytz (2017.2)

requests (2.18.4)

setuptools (36.5.0)

six (1.10.0)

urllib3 (1.22)

Werkzeug (0.12.2)

wheel (0.30.0)

Globally installed Python packages:

root@ub50368:/var/www/sites/api# pip3.6 list

pip (9.0.1)

setuptools (28.8.0)

virtualenv (15.1.0)

WSGI Directives from Apache2 configuration:

WSGIDaemonProcess rest_api_v1 user=api group=api home=/var/www/sites/api python-home=/var/www/sites/api/venv

WSGIProcessGroup rest_api_v1

#WSGIApplicationGroup %{GLOBAL}

WSGIScriptAlias / /var/www/sites/api/start.wsgi

Things we've tried:

• Installing requests (& all pip packages) globally and disabling the python-home parameter
  
• Rebuilding the virtualenv
• Installing requests directly from git/source
• Using the activate_this.py - http://flask.pocoo.org/docs/0.12/deploying/mod_wsgi/#working-with-virtual-environments
• Embedding the requests source directly in the Flask app

Does anyone have any idea of what could be going wrong, or how to dive deeper into the problem? 

Thanks,

Chris

[Bill Freeman]

Do you have a module of your own named "requests" that is being confused, somehow, with the installed package?

Or might you be importing something "as requests"?

--
You received this message because you are subscribed to the Google Groups "modwsgi" group.
To unsubscribe from this group and stop receiving emails from it, send an email to modwsgi+unsubscribe@googlegroups.com.
To post to this group, send email to mod...@googlegroups.com.
Visit this group at https://groups.google.com/group/modwsgi.
For more options, visit https://groups.google.com/d/optout.

[Graham Dumpleton]

On 29 Sep 2017, at 5:51 am, Bill Freeman <ke1...@gmail.com> wrote:

Do you have a module of your own named "requests" that is being confused, somehow, with the installed package?

Or might you be importing something "as requests"?

The way to determine that is to add somewhere in your code:

    import requests

    print('requests.__file__', requests.__file__)

Then check the logs for where it says the module file is being imported.

Graham

To unsubscribe from this group and stop receiving emails from it, send an email to modwsgi+u...@googlegroups.com.

[Chris Barton]

Hi Bill,

Thanks for your reply. This was one of the first things we looked at a week or two ago. We even tried importing requests as a different module name. 

This exact same code will run properly when the Flask module is run directly with the python interpreter from our virtualenv. If we were clobbering the name "requests" I would expect to encounter errors when running outside of Apache & mod_wsgi as well.

Regards,

Chris

To unsubscribe from this group and stop receiving emails from it, send an email to modwsgi+u...@googlegroups.com.

[Chris Barton]

Hi Graham,

Here's what we're getting when we attempt to access the __file__ attribute of the imported requests library:

[Thu Sep 28 15:37:30.406608 2017] [wsgi:info] [pid 9408:tid 139645478971136] mod_wsgi (pid=9408): Create interpreter 'dev.api.serviceoperations.mydomain.com|'.

[Thu Sep 28 15:37:30.422457 2017] [wsgi:info] [pid 9408:tid 139645478971136] [remote 10.6.70.171:49215] mod_wsgi (pid=9408, process='rest_api_v1', application='dev.api.serviceoperations.mydomain.com|'): Loading WSGI script '/var/www/sites/api/start.wsgi'.

[Thu Sep 28 15:37:31.003398 2017] [wsgi:error] [pid 9408:tid 139645478971136] [remote 10.6.70.171:49215] mod_wsgi (pid=9408): Target WSGI script '/var/www/sites/api/start.wsgi' cannot be loaded as Python module.

[Thu Sep 28 15:37:31.003458 2017] [wsgi:error] [pid 9408:tid 139645478971136] [remote 10.6.70.171:49215] mod_wsgi (pid=9408): Exception occurred processing WSGI script '/var/www/sites/api/start.wsgi'.

[Thu Sep 28 15:37:31.003834 2017] [wsgi:error] [pid 9408:tid 139645478971136] [remote 10.6.70.171:49215] Traceback (most recent call last):

[Thu Sep 28 15:37:31.003938 2017] [wsgi:error] [pid 9408:tid 139645478971136] [remote 10.6.70.171:49215]   File "/var/www/sites/api/start.wsgi", line 11, in <module>

[Thu Sep 28 15:37:31.003954 2017] [wsgi:error] [pid 9408:tid 139645478971136] [remote 10.6.70.171:49215]     from rest_api_v1 import app as application

[Thu Sep 28 15:37:31.003963 2017] [wsgi:error] [pid 9408:tid 139645478971136] [remote 10.6.70.171:49215]   File "/var/www/sites/api/rest_api_v1/__init__.py", line 34, in <module>

[Thu Sep 28 15:37:31.004012 2017] [wsgi:error] [pid 9408:tid 139645478971136] [remote 10.6.70.171:49215]     print('requests.__file__', requests.__file__)

[Thu Sep 28 15:37:31.004112 2017] [wsgi:error] [pid 9408:tid 139645478971136] [remote 10.6.70.171:49215] AttributeError: module 'requests' has no attribute '__file__'

[Thu Sep 28 15:37:31.004266 2017] [headers:debug] [pid 9409:tid 139645425809152] mod_headers.c(899): AH01503: headers: ap_headers_error_filter()

We've previously tried printing out all of the attributes of requests after it is imported and a severely truncated list of attributes is provided back:

[

    "__doc__",

    "__loader__",

    "__name__",

    "__package__",

    "__path__",

    "__spec__"

  ]

Here's the contents of requests.__path__ during runtime:

[Thu Sep 28 15:54:21.196608 2017] [wsgi:error] [pid 11443:tid 140183901226752] requests.__path__ : _NamespacePath(['/var/www/sites/api/venv/lib/python3.6/site-packages/requests'])

Manually running the Flask package I get the expected results from the print statement:

(venv) root@ub50368:/var/www/sites/api# python rest_api_v1/

requests.__file__ /var/www/sites/api/venv/lib/python3.6/site-packages/requests/__init__.py

 * Running on http://0.0.0.0:5000/ (Press CTRL+C to quit)

 * Restarting with stat

requests.__file__ /var/www/sites/api/venv/lib/python3.6/site-packages/requests/__init__.py

 * Debugger is active!

 * Debugger PIN: 217-497-265

To unsubscribe from this group and stop receiving emails from it, send an email to modwsgi+u...@googlegroups.com.
To post to this group, send email to mod...@googlegroups.com.
Visit this group at https://groups.google.com/group/modwsgi.
For more options, visit https://groups.google.com/d/optout.

[Graham Dumpleton]

What do you get if you add:

    import sys

    import requests

    print(type(sys.modules['requests'])

    print(type(requests))

It looks a bit like some fancy is being done with delayed module loader as a real module should have a __file__ attribute.

Graham

[Chris Barton]

Graham,

Thanks for getting back to us so quickly. We've decided to write a small test app so that we can share the code we are running. It should be attached to this post. The relevant output lines have been bolded in the output below:

[Fri Sep 29 08:03:43.863047 2017] [wsgi:info] [pid 43865:tid 140413003486976] mod_wsgi (pid=43865): Create interpreter 'dev.api.serviceoperations.mydomain.com|'.

[Fri Sep 29 08:03:43.888707 2017] [wsgi:info] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127] mod_wsgi (pid=43865, process='rest_api_v1', application='dev.api.serviceoperations.mydomain.com|'): Loading WSGI script '/var/www/sites/api/start.wsgi'.

[Fri Sep 29 08:03:44.430607 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127] <class 'module'>

[Fri Sep 29 08:03:44.430638 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127] <class 'module'>

[Fri Sep 29 08:03:44.433186 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127] [2017-09-29 08:03:44,431] ERROR in app: Exception on /test [GET]

[Fri Sep 29 08:03:44.433198 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127] Traceback (most recent call last):

[Fri Sep 29 08:03:44.433201 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/app.py", line 1982, in wsgi_app

[Fri Sep 29 08:03:44.433204 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]     response = self.full_dispatch_request()

[Fri Sep 29 08:03:44.433206 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/app.py", line 1614, in full_dispatch_request

[Fri Sep 29 08:03:44.433209 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]     rv = self.handle_user_exception(e)

[Fri Sep 29 08:03:44.433211 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask_cors/extension.py", line 161, in wrapped_function

[Fri Sep 29 08:03:44.433214 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]     return cors_after_request(app.make_response(f(*args, **kwargs)))

[Fri Sep 29 08:03:44.433216 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/app.py", line 1517, in handle_user_exception

[Fri Sep 29 08:03:44.433218 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]     reraise(exc_type, exc_value, tb)

[Fri Sep 29 08:03:44.433220 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/_compat.py", line 33, in reraise

[Fri Sep 29 08:03:44.433222 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]     raise value

[Fri Sep 29 08:03:44.433225 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/app.py", line 1612, in full_dispatch_request

[Fri Sep 29 08:03:44.433227 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]     rv = self.dispatch_request()

[Fri Sep 29 08:03:44.433229 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]   File "/var/www/sites/api/venv/lib/python3.6/site-packages/flask/app.py", line 1598, in dispatch_request

[Fri Sep 29 08:03:44.433237 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]     return self.view_functions[rule.endpoint](**req.view_args)

[Fri Sep 29 08:03:44.433239 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]   File "/var/www/sites/api/test_app/endpoints/test_post.py", line 8, in test

[Fri Sep 29 08:03:44.433242 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]     return logic.test()

[Fri Sep 29 08:03:44.433244 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]   File "/var/www/sites/api/test_app/logic/test_post.py", line 12, in test

[Fri Sep 29 08:03:44.433246 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127]     r = requests.get(URL)

[Fri Sep 29 08:03:44.433249 2017] [wsgi:error] [pid 43865:tid 140413003486976] [remote 10.6.70.171:56127] AttributeError: module 'requests' has no attribute 'get'

Regards,

Chris

[Graham Dumpleton]

Sorry for slow reply, was busy weekend.

I can't reproduce this issue with your code by doing the following:

1. Create fresh Python virtualenv and activate it.

2. Install packages from requirements.txt.

3. Install mod_wsgi using pip to get mod_wsgi-express.

4. Fix start.wsgi to use:

    #sys.path.insert(0, '/var/www/sites/api/')

    sys.path.insert(0, os.path.dirname(__file__))

Although not strictly needed as am running with mod_wsgi-express out of that directory anyway.

5. Run mod_wsgi-express as:

    mod_wsgi-express start-server start.wsgi

6. Hit endpoint.

    curl http://localhost:8000/test

Perhaps you can try the same with fresh virtualenv and then try it with existing virtualenv. Maybe it will show out something as being strange in your virtualenv, or that it comes back to how things are setup with your main Apache installation.

Graham

<test_app.tar>

[Chris Barton]

Graham,

Thank you for your time helping look into this. Our code worked properly against mod_wsgi-express built against Python3.5. The module that mod_wsgi-express compiled works flawlessly in our apache2 installation. Nothing else was changed, which I suppose suggests that the version of mod_wsgi that I had previously compiled was the problem.

Great work on mod_wsgi-express!

[Graham Dumpleton]

There are no notable differences between mod_wsgi 4.5.18 which you said you were using and the latest version, and I don't know of reason why a configure/make/make install version, vs pip install version would make a difference. So not sure why it would make a difference. Anyway, sounds like it works now, which is good.

Graham