No such file or directory: '/var/tmp/ckan/dynamic_menu/menu.json' when running catalog with Apache on startup

[adborden]

There are multiple compounding issues here, so I'll go through them here and link out to other issues as necessary.

When running the catalog app behind Apache in the docker container, we get a 500 when trying to view /dataset (and probably most routes that use that header template). /var/tmp/ckan/dynamic_menu/menu.json is missing, so the request fails. menu.json is part of ckanext-datagovtheme and is fetched from the production wordpress site (data.gov) at request time if it is stale (>30 minutes old). On initial startup, that file will not exist and so needs to be fetched. This is the stack trace from the initial log:

...
[Thu Aug 09 00:35:43.040315 2018] [:error] [pid 74:tid 139721653876480] [remote 172.17.0.1:62595]   File "/usr/lib/ckan/src/ckan/ckan/templates/page.html", line 15, in block "header"
[Thu Aug 09 00:35:43.040334 2018] [:error] [pid 74:tid 139721653876480] [remote 172.17.0.1:62595]     {% include "header.html" %}
[Thu Aug 09 00:35:43.040342 2018] [:error] [pid 74:tid 139721653876480] [remote 172.17.0.1:62595]   File "/usr/lib/ckan/src/ckanext-datagovtheme/ckanext/datagovtheme/templates/header.html", line 1, in top-level template code
[Thu Aug 09 00:35:43.040363 2018] [:error] [pid 74:tid 139721653876480] [remote 172.17.0.1:62595]     {% block header %}
[Thu Aug 09 00:35:43.040371 2018] [:error] [pid 74:tid 139721653876480] [remote 172.17.0.1:62595]   File "/usr/lib/ckan/src/ckanext-datagovtheme/ckanext/datagovtheme/templates/header.html", line 2, in block "header"
[Thu Aug 09 00:35:43.040390 2018] [:error] [pid 74:tid 139721653876480] [remote 172.17.0.1:62595]     {% set menus = h.get_dynamic_menu() %}
[Thu Aug 09 00:35:43.040399 2018] [:error] [pid 74:tid 139721653876480] [remote 172.17.0.1:62595]   File "/usr/lib/ckan/src/ckanext-datagovtheme/ckanext/datagovtheme/helpers.py", line 110, in get_dynamic_menu
[Thu Aug 09 00:35:43.040419 2018] [:error] [pid 74:tid 139721653876480] [remote 172.17.0.1:62595]     file_obj = open(filename)
[Thu Aug 09 00:35:43.040443 2018] [:error] [pid 74:tid 139721653876480] [remote 172.17.0.1:62595] IOError: [Errno 2] No such file or directory: '/var/tmp/ckan/dynamic_menu/menu.json'

Full stack trace

The underlying issue is that the fetch fails. After the first fetch, the stale file is used as a fallback, so this only applies to a new instance and the first startup. Here's the underlying exception for the fetch which does not appear in the logs:

[Thu Aug 09 00:35:43.035607 2018] [:error] [pid 74:tid 139721653876480] 2018-08-09 00:35:43,035 ERROR [ckanext.datagovtheme.helpers] dynamic menu url failed to fetch
[Thu Aug 09 00:35:43.035642 2018] [:error] [pid 74:tid 139721653876480] Traceback (most recent call last):
[Thu Aug 09 00:35:43.035647 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/ckan/src/ckanext-datagovtheme/ckanext/datagovtheme/helpers.py", line 107, in get_dynamic_men
u
[Thu Aug 09 00:35:43.035651 2018] [:error] [pid 74:tid 139721653876480]     resource = urllib2.urlopen(url, timeout=sec_timeout)
[Thu Aug 09 00:35:43.035655 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 127, in urlopen
[Thu Aug 09 00:35:43.035658 2018] [:error] [pid 74:tid 139721653876480]     return _opener.open(url, data, timeout)
[Thu Aug 09 00:35:43.035661 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 410, in open
[Thu Aug 09 00:35:43.035664 2018] [:error] [pid 74:tid 139721653876480]     response = meth(req, response)
[Thu Aug 09 00:35:43.035668 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 523, in http_response
[Thu Aug 09 00:35:43.035684 2018] [:error] [pid 74:tid 139721653876480]     'http', request, response, code, msg, hdrs)
[Thu Aug 09 00:35:43.035688 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 442, in error
[Thu Aug 09 00:35:43.035691 2018] [:error] [pid 74:tid 139721653876480]     result = self._call_chain(*args)
[Thu Aug 09 00:35:43.035695 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 382, in _call_chain
[Thu Aug 09 00:35:43.035698 2018] [:error] [pid 74:tid 139721653876480]     result = func(*args)
[Thu Aug 09 00:35:43.035702 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 629, in http_error_302
[Thu Aug 09 00:35:43.035705 2018] [:error] [pid 74:tid 139721653876480]     return self.parent.open(new, timeout=req.timeout)
[Thu Aug 09 00:35:43.035708 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 404, in open
[Thu Aug 09 00:35:43.035711 2018] [:error] [pid 74:tid 139721653876480]     response = self._open(req, data)
[Thu Aug 09 00:35:43.035715 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 422, in _open
[Thu Aug 09 00:35:43.035718 2018] [:error] [pid 74:tid 139721653876480]     '_open', req)
[Thu Aug 09 00:35:43.035722 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 382, in _call_chain
[Thu Aug 09 00:35:43.035725 2018] [:error] [pid 74:tid 139721653876480]     result = func(*args)
[Thu Aug 09 00:35:43.035729 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 1222, in https_open
[Thu Aug 09 00:35:43.035732 2018] [:error] [pid 74:tid 139721653876480]     return self.do_open(httplib.HTTPSConnection, req)
[Thu Aug 09 00:35:43.035736 2018] [:error] [pid 74:tid 139721653876480]   File "/usr/lib/python2.7/urllib2.py", line 1184, in do_open
[Thu Aug 09 00:35:43.035739 2018] [:error] [pid 74:tid 139721653876480]     raise URLError(err)
[Thu Aug 09 00:35:43.035743 2018] [:error] [pid 74:tid 139721653876480] URLError: <urlopen error [Errno 1] _ssl.c:510: error:14077410:SSL routines:SSL23_GET_SERVER_HELLO:sslv3 alert handshake failure>

This shows the system python 2.7.6 version of urllib2 is being used and is failing the SSL handshake. I suspect the wordpress site "recently" deprecated old SSL versions, so this version of urllib2 no longer works.

We are building our own version of python (2.7.10) for the virtualenv, but because we're using the OS libapache2-mod-wsgi, it is built against the system python and will not use our 2.7.10 core python libraries. Setting WSGIPythonHome results in another import error from missing TLS methods. I'm not 100% sure on this, but I think if we want WSGI to use our version of python, we need to build it ourselves. This isn't necessarily the right path forward, but we should be making sure python versions being used in production (by WSGI) is what we're using in dev.

[adborden]

Confirmed that www.data.gov does not support SSL2 or SSL3 or TLS1. Only modern versions of TLS.

[adborden]

In digging into this, I realized that our custom python is built statically. When using WSGIPythonHome, the import error I saw was a mismatch in the hmac internals, same error here which is the result of the python code not matching the native code. mod_wsgi recommends building python as a shared library and after doing that WSGIPythonHome works as expected without rebuilding mod_wsgi. The only reason you would need to rebuild mod_wsgi is if we were using a different major/minor version of python.

So I think the fix for this issue is to just build our custom python as a shared library (--enable-shared) and use WSGIPythonHome <vitualenv> instead of activating the virtualenv in the wsgi script. We'll want to update the ansible playbooks too since this affects production.

[JJediny]

@adborden so is the proposed solution to activate the python virtualenv with --enabled-shared?

[adborden]

It's actually in how Python is compiled. --ensure-shared needs to be passed to the ./configure command.

[adborden]

Re-opening. It looks like if the fetch fails, we still fall back to updating the timestamp on the file, but if the file never existed, you'll get this error.

[Wed Mar 18 20:17:40.512727 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckan/ckan/lib/base.py", line 104, in render_jinja2
[Wed Mar 18 20:17:40.512736 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     return template.render(**extra_vars)
[Wed Mar 18 20:17:40.512741 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan/lib/python2.7/site-packages/newrelic/api/function_trace.py", line 131, in dynamic_wrapper
[Wed Mar 18 20:17:40.512750 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     return wrapped(*args, **kwargs)
[Wed Mar 18 20:17:40.512756 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan/lib/python2.7/site-packages/jinja2/environment.py", line 894, in render
[Wed Mar 18 20:17:40.512767 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     return self.environment.handle_exception(exc_info, True)
[Wed Mar 18 20:17:40.512772 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckan/ckan/templates/error_document_template.html", line 1, in top-level template code
[Wed Mar 18 20:17:40.512783 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {% extends "page.html" %}
[Wed Mar 18 20:17:40.512789 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckanext-datagovtheme/ckanext/datagovtheme/templates/page.html", line 1, in top-level template code
[Wed Mar 18 20:17:40.512799 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {% ckan_extends %}
[Wed Mar 18 20:17:40.512805 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckan/ckan/templates/page.html", line 1, in top-level template code
[Wed Mar 18 20:17:40.512817 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {% extends "base.html" %}
[Wed Mar 18 20:17:40.512823 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckanext-harvest/ckanext/harvest/templates_new/base.html", line 1, in top-level template code
[Wed Mar 18 20:17:40.512834 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {% ckan_extends %}
[Wed Mar 18 20:17:40.512840 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckanext-datagovtheme/ckanext/datagovtheme/templates/base.html", line 1, in top-level template code
[Wed Mar 18 20:17:40.512850 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {% ckan_extends %}
[Wed Mar 18 20:17:40.512856 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckanext-googleanalyticsbasic/ckanext/googleanalyticsbasic/templates/base.html", line 1, in top-level template code
[Wed Mar 18 20:17:40.512866 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {% ckan_extends %}
[Wed Mar 18 20:17:40.512872 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckanext-extlink/ckanext/extlink/templates/base.html", line 1, in top-level template code
[Wed Mar 18 20:17:40.512886 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {% ckan_extends %}
[Wed Mar 18 20:17:40.512892 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckan/ckan/templates/base.html", line 103, in top-level template code
[Wed Mar 18 20:17:40.512902 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {%- block page %}{% endblock -%}
[Wed Mar 18 20:17:40.512907 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckan/ckan/templates/page.html", line 14, in block "page"
[Wed Mar 18 20:17:40.512916 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {%- block header %}
[Wed Mar 18 20:17:40.512922 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckan/ckan/templates/page.html", line 15, in block "header"
[Wed Mar 18 20:17:40.512931 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {% include "header.html" %}
[Wed Mar 18 20:17:40.512936 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckanext-datagovtheme/ckanext/datagovtheme/templates/header.html", line 1, in top-level template code
[Wed Mar 18 20:17:40.512946 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {% block header %}
[Wed Mar 18 20:17:40.512952 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckanext-datagovtheme/ckanext/datagovtheme/templates/header.html", line 2, in block "header"
[Wed Mar 18 20:17:40.513007 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     {% set menus = h.get_dynamic_menu() %}
[Wed Mar 18 20:17:40.513018 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]   File "/usr/lib/ckan-new/src/ckanext-datagovtheme/ckanext/datagovtheme/helpers.py", line 107, in get_dynamic_menu
[Wed Mar 18 20:17:40.513031 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122]     file_obj = open(filename)
[Wed Mar 18 20:17:40.513046 2020] [wsgi:error] [pid 26264:tid 140025841866496] [remote 127.0.0.1:60122] IOError: [Errno 2] No such file or directory: '/var/tmp/ckan/dynamic_menu/menu.json'