Long Run: Horizon failed with 500 internal server error

[Timur Nurlygayanov]

Possible workaround:
restart apache2 service on all controller nodes.

Steps To Reproduce:
1. Deploy OpenStack cluster with 3 controllers with vbox scripts
2. Wait 1 week
3. Open Horizon index page: https://172.16.0.3/horizon

Expected Result:
User can successfully open Horizon UI

Observed Result:
User can see error: 500: Internal server error.

When we restart apache2 service we will see the following warnings and errors:

root@node-3:~# service apache2 restart
 * Restarting web server apache2 AH00316: WARNING: MaxRequestWorkers of 798 is not an integer multiple of
 ThreadsPerChild of 25, decreasing to nearest multiple 775,
 for a maximum of 31 servers.
(98)Address already in use: AH00072: make_sock: could not bind to address [::]:35357
(98)Address already in use: AH00072: make_sock: could not bind to address 0.0.0.0:35357
no listening sockets available, shutting down
AH00015: Unable to open logs
Action 'start' failed.
The Apache error log may have more information.

Reproduced on

VERSION:
  feature_groups:
    - mirantis
  production: "docker"
  release: "8.0"
  openstack_version: "2015.1.0-8.0"
  api: "1.0"
  build_number: "227"
  build_id: "227"
  fuel-nailgun_sha: "28025f978a6c5d23e7441ad3ec8c2b9f123d9d15"
  python-fuelclient_sha: "b77559b309a62650658424a43051cfeaba518748"
  fuel-agent_sha: "1672c18c8193e1b93d5687d8b720cf4f1ea07048"
  fuel-nailgun-agent_sha: "a33a58d378c117c0f509b0e7badc6f0910364154"
  astute_sha: "b60624ee2c5f1d6d805619b6c27965a973508da1"
  fuel-library_sha: "b9f8c28f0e8f7d725ed4211df418fc54a1abd728"
  fuel-ostf_sha: "fc6648be21f26fac4f66ef18ba36f521960d554b"
  fuel-createmirror_sha: "1f3b4ae09d01591e59449448955dd4254b38ce23"
  fuelmenu_sha: "4064b7723773ab89cdfcbf6cf4682215a7757104"
  shotgun_sha: "25a0cc461a9fa4f7684f04cef0ff4ad9aa99a64d"
  network-checker_sha: "0b1b94a9685c6471d6911dff7ecac10b7bd2625f"
  fuel-upgrade_sha: "1e894e26d4e1423a9b0d66abd6a79505f4175ff6"
  fuelmain_sha: "2eca6adc33f02e02cd812e1d4be7c70e05fd07db"

[Timur Nurlygayanov (tnurlygayanov)]

Apache logs:

root@node-2:~# tail -n 200 -f /var/log/apache2/error.log
[Mon Dec 14 08:12:32.735850 2015] [mpm_event:notice] [pid 4331:tid 140553176475520] AH00489: Apache/2.4.7 (Ubuntu) configured -- resuming normal operations
[Mon Dec 14 08:12:32.735930 2015] [core:notice] [pid 4331:tid 140553176475520] AH00094: Command line: '/usr/sbin/apache2'
[Mon Dec 14 08:12:36.236677 2015] [mpm_event:notice] [pid 4331:tid 140553176475520] AH00491: caught SIGTERM, shutting down
[Mon Dec 14 08:12:36.461300 2015] [mpm_worker:notice] [pid 4674:tid 140649956820864] AH00292: Apache/2.4.7 (Ubuntu) configured -- resuming normal operations
[Mon Dec 14 08:12:36.461329 2015] [core:notice] [pid 4674:tid 140649956820864] AH00094: Command line: '/usr/sbin/apache2'
[Mon Dec 14 08:13:18.850868 2015] [mpm_worker:notice] [pid 4674:tid 140649956820864] AH00297: SIGUSR1 received. Doing graceful restart
[Mon Dec 14 08:13:18.854440 2015] [mpm_worker:warn] [pid 4674:tid 140649956820864] AH00317: MaxRequestWorkers of 798 is not an integer multiple of ThreadsPerChild of 25, decreasing to nearest multiple 775
[Mon Dec 14 08:13:18.854740 2015] [mpm_worker:notice] [pid 4674:tid 140649956820864] AH00292: Apache/2.4.7 (Ubuntu) configured -- resuming normal operations
[Mon Dec 14 08:13:18.854746 2015] [core:notice] [pid 4674:tid 140649956820864] AH00094: Command line: '/usr/sbin/apache2'
[Mon Dec 14 08:17:35.333464 2015] [mpm_worker:notice] [pid 4674:tid 140649956820864] AH00297: SIGUSR1 received. Doing graceful restart
[Mon Dec 14 08:17:35.336561 2015] [mpm_worker:warn] [pid 4674:tid 140649956820864] AH00317: MaxRequestWorkers of 798 is not an integer multiple of ThreadsPerChild of 25, decreasing to nearest multiple 775
[Mon Dec 14 08:17:35.336882 2015] [mpm_worker:notice] [pid 4674:tid 140649956820864] AH00292: Apache/2.4.7 (Ubuntu) configured -- resuming normal operations
[Mon Dec 14 08:17:35.336889 2015] [core:notice] [pid 4674:tid 140649956820864] AH00094: Command line: '/usr/sbin/apache2'
[Mon Dec 14 08:17:53.578509 2015] [mpm_worker:notice] [pid 4674:tid 140649956820864] AH00295: caught SIGTERM, shutting down
[Mon Dec 14 08:17:54.325429 2015] [mpm_worker:notice] [pid 3988:tid 139719608993664] AH00292: Apache/2.4.7 (Ubuntu) mod_wsgi/3.4 Python/2.7.6 configured -- resuming normal operations
[Mon Dec 14 08:17:54.325462 2015] [core:notice] [pid 3988:tid 139719608993664] AH00094: Command line: '/usr/sbin/apache2'
[Mon Dec 14 08:18:28.572007 2015] [mpm_worker:notice] [pid 3988:tid 139719608993664] AH00297: SIGUSR1 received. Doing graceful restart
[Mon Dec 14 08:18:28.581871 2015] [mpm_worker:warn] [pid 3988:tid 139719608993664] AH00317: MaxRequestWorkers of 798 is not an integer multiple of ThreadsPerChild of 25, decreasing to nearest multiple 775
[Mon Dec 14 08:18:28.583127 2015] [mpm_worker:notice] [pid 3988:tid 139719608993664] AH00292: Apache/2.4.7 (Ubuntu) mod_wsgi/3.4 Python/2.7.6 configured -- resuming normal operations
[Mon Dec 14 08:18:28.583155 2015] [core:notice] [pid 3988:tid 139719608993664] AH00094: Command line: '/usr/sbin/apache2'
[Mon Dec 14 08:26:08.311634 2015] [mpm_worker:notice] [pid 3988:tid 139719608993664] AH00297: SIGUSR1 received. Doing graceful resta...

[Timur Sufiev (tsufiev-x)]

Unfortunately, no information regarding the 500 error could be find in attached logs. Please, provide /var/log/apache/horizon_error.log and /var/log/horizon/horizon.log

[Timur Nurlygayanov (tnurlygayanov)]

Timur, first file doesn't exist, the second one is empty on this environment.

[Timur Sufiev (tsufiev-x)]

I've found the most likely cause of 500 error on node-3 /var/log/apache/horizon_error.log (node-2 and node-1 corresponding files were empty indeed).

Mon Dec 14 11:55:28.290869 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] mod_wsgi (pid=24944): Exception occurred processing WSGI script '/usr/share/openstack-das
hboard/openstack_dashboard/wsgi/django.wsgi'.
[Mon Dec 14 11:55:28.290912 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] Traceback (most recent call last):
[Mon Dec 14 11:55:28.290931 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] File "/usr/lib/python2.7/dist-packages/django/core/handlers/wsgi.py", line 168, in __ca
ll__
[Mon Dec 14 11:55:28.291025 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] self.load_middleware()
[Mon Dec 14 11:55:28.291039 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] File "/usr/lib/python2.7/dist-packages/django/core/handlers/base.py", line 46, in load_
middleware
[Mon Dec 14 11:55:28.291108 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] mw_instance = mw_class()
[Mon Dec 14 11:55:28.291118 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] File "/usr/lib/python2.7/dist-packages/django/middleware/locale.py", line 23, in __init
__
[Mon Dec 14 11:55:28.291154 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] for url_pattern in get_resolver(None).url_patterns:
[Mon Dec 14 11:55:28.291164 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] File "/usr/lib/python2.7/dist-packages/django/core/urlresolvers.py", line 372, in url_patterns
[Mon Dec 14 11:55:28.291308 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] patterns = getattr(self.urlconf_module, "urlpatterns", self.urlconf_module)
[Mon Dec 14 11:55:28.291322 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] File "/usr/lib/python2.7/dist-packages/django/core/urlresolvers.py", line 366, in urlconf_module
[Mon Dec 14 11:55:28.291336 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] self._urlconf_module = import_module(self.urlconf_name)
[Mon Dec 14 11:55:28.291342 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] File "/usr/lib/python2.7/importlib/__init__.py", line 37, in import_module
[Mon Dec 14 11:55:28.291375 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] __import__(name)
[Mon Dec 14 11:55:28.291382 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] File "/usr/share/openstack-dashboard/openstack_dashboard/wsgi/../../openstack_dashboard/urls.py", line 35, in <module>
[Mon Dec 14 11:55:28.291414 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] url(r'^api/', include('openstack_dashboard.api.rest.urls')),
[Mon Dec 14 11:55:28.291422 2015] [:error] [pid 24944:tid 140366006642432] [remote 192.168.0.7:3209] File "/usr/lib/python2.7/dist-packages/django/conf/urls/__init__.py", line 28, in include
[Mon Dec 14 11:55:28.291453 2015] [:error] [pid 24...

[Timur Sufiev (tsufiev-x)]

So I've googled 'osrandom engine already registered' error a bit and found this: https://github.com/pyca/cryptography/pull/2293
Reassiging to mos-linux, since it seems their are of expertise.

[Dmitry Teselkin (teselkin-d)]

In [1] there is fix for that issue - update cryptography package to 1.1.
There is another bug [2] that suggests the same.
Version 1.1 fits global requirements [3].

Reassigning to mos-packaging.

[1] https://github.com/pyca/cryptography/issues/2287
[2] https://bugzilla.redhat.com/show_bug.cgi?id=1284148
[3] https://github.com/openstack/requirements/blob/stable/liberty/global-requirements.txt#L25

[Fuel Devops McRobotson (fuel-devops-robot)]

Related fix proposed to branch: master
Change author: Mikhail Ivanov <email address hidden>
Review: https://review.fuel-infra.org/16447

[Fuel Devops McRobotson (fuel-devops-robot)]

Fix proposed to branch: master
Change author: Mikhail Ivanov <email address hidden>
Review: https://review.fuel-infra.org/16449

[Fuel Devops McRobotson (fuel-devops-robot)]

Reviewed: https://review.fuel-infra.org/16447
Submitter: Pkgs Jenkins <email address hidden>
Branch: master

Commit: 645765d9c440ff10a6083721f2f5ce0a64fcb172
Author: Mikhail Ivanov <email address hidden>
Date: Mon Jan 25 16:47:36 2016

Update python-cryptography to v1.1

  * Update to new upstream version
  * Sources from:
    https://pypi.python.org/packages/source/c/cryptography-vectors/cryptography_vectors-1.1.tar.gz
Related-Bug:#1525877

Change-Id: I6c690fd76ed2dc31a148e0251dfb23025d6b2233

[Fuel Devops McRobotson (fuel-devops-robot)]

Reviewed: https://review.fuel-infra.org/16449
Submitter: Pkgs Jenkins <email address hidden>
Branch: master

Commit: 454dedba199fa539856b79f83a984f29ab29a8ba
Author: Mikhail Ivanov <email address hidden>
Date: Mon Jan 25 17:17:31 2016

update python-cryptography to v1.1

  * Update to new upstream version
  * Sources from:
    https://pypi.python.org/packages/source/c/cryptography/cryptography-1.1.tar.gz
Closes-Bug:#1525877

Change-Id: I0ec35ec7f1211e4ccd11b2d4c82c547e209f1ecf

[Alexander Nagovitsyn (gluk12189)]

I have some error on mos-490 and 492 build

sudo service apache2 start
 * Starting web server apache2 AH00316: WARNING: MaxRequestWorkers of 779 is not an integer multiple of
 ThreadsPerChild of 25, decreasing to nearest multiple 775,
 for a maximum of 31 servers.
(98)Address already in use: AH00072: make_sock: could not bind to address 192.168.0.4:35357
no listening sockets available, shutting down
AH00015: Unable to open logs
Action 'start' failed.

[Alexander Nagovitsyn (gluk12189)]

Apache2 erros log:

[Thu Jun 16 10:25:10.460849 2016] [core:notice] [pid 18300:tid 139860243507072] AH00094: Command line: '/usr/sbin/apache2'
[Thu Jun 16 10:26:02.201702 2016] [mpm_worker:notice] [pid 18300:tid 139860243507072] AH00297: SIGUSR1 received. Doing graceful restart
[Thu Jun 16 10:26:02.962881 2016] [mpm_worker:warn] [pid 18300:tid 139860243507072] AH00317: MaxRequestWorkers of 779 is not an integer multiple of ThreadsPerChild of 25, decreasing to nearest multiple 775
[Thu Jun 16 10:26:02.969171 2016] [mpm_worker:notice] [pid 18300:tid 139860243507072] AH00292: Apache/2.4.7 (Ubuntu) mod_wsgi/4.4.15 Python/2.7.6 configured -- resuming normal operations
[Thu Jun 16 10:26:02.969193 2016] [core:notice] [pid 18300:tid 139860243507072] AH00094: Command line: '/usr/sbin/apache2'
[Thu Jun 16 10:31:26.271805 2016] [mpm_worker:notice] [pid 18300:tid 139860243507072] AH00297: SIGUSR1 received. Doing graceful restart
[Thu Jun 16 10:31:27.806332 2016] [mpm_worker:warn] [pid 18300:tid 139860243507072] AH00317: MaxRequestWorkers of 779 is not an integer multiple of ThreadsPerChild of 25, decreasing to nearest multiple 775
[Thu Jun 16 10:31:27.816193 2016] [mpm_worker:notice] [pid 18300:tid 139860243507072] AH00292: Apache/2.4.7 (Ubuntu) mod_wsgi/4.4.15 Python/2.7.6 configured -- resuming normal operations
[Thu Jun 16 10:31:27.816220 2016] [core:notice] [pid 18300:tid 139860243507072] AH00094: Command line: '/usr/sbin/apache2'
[Fri Jun 17 11:36:49.071008 2016] [mpm_worker:notice] [pid 18300:tid 139860243507072] AH00295: caught SIGTERM, shutting down

[Ivan Udovichenko (iudovichenko)]

Alexander, please elaborate on comments you have provided. Also please provide steps to reproduce the issue. Information on how the issue is related to Horizon will be highly appreciated.

[Timur Sufiev (tsufiev-x)]

Alexander, as before we need horizon logs, this time from /var/log/horizon/horizon.log - if this is really about horizon.