1452390 – rhosp-director: ERROR: Failed running docker-puppet.py for keystone_init_tasks

Bug 1452390 - rhosp-director: ERROR: Failed running docker-puppet.py for keystone_init_tasks

Summary: rhosp-director: ERROR: Failed running docker-puppet.py for keystone_init_tasks

Keywords:
Status:	CLOSED WORKSFORME
Alias:	None
Product:	Red Hat OpenStack
Classification:	Red Hat
Component:	rhosp-director
Sub Component:
Version:	12.0 (Pike)
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	high
Target Milestone:	ga
Target Release:	12.0 (Pike)
Assignee:	Angus Thomas
QA Contact:	Omri Hochman
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2017-05-18 20:46 UTC by Alexander Chuzhoy
Modified:	2017-06-16 15:10 UTC (History)
CC List:	9 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2017-06-16 15:10:33 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
sosreport from controller (10.08 MB, application/x-xz) 2017-05-18 20:52 UTC, Alexander Chuzhoy	no flags	Details
View All

Description Alexander Chuzhoy 2017-05-18 20:46:40 UTC

rhosp-director: ERROR: Failed running docker-puppet.py for keystone_init_tasks

Environment:
openstack-tripleo-heat-templates-7.0.0-0.20170512193554.el7ost.noarch
instack-undercloud-7.0.0-0.20170503001109.el7ost.noarch
openstack-puppet-modules-10.0.0-0.20170315222135.0333c73.el7.1.noarch



Steps to reproduce:
Run the OC deployment:
openstack overcloud deploy --templates --libvirt-type kvm -e /usr/share/openstack-tripleo-heat-templates/environments/docker.yaml -e /home/stack/templates/docker-osp12.yaml -e /home/stack/templates/nodes_data.yaml


Result:

    Error: Failed to apply catalog: Execution of '/usr/bin/openstack domain list --quiet --format csv' returned 1: An unexpected error prevented the server from fulfilling your request. (HTTP 500) (Request-ID: req-80ffb9f7-75ca-4e96-a40d-913b38169ec2) (tried 42, for a total of 170 seconds)
    
    2017-05-18 20:36:00,076 ERROR: Failed running docker-puppet.py for keystone_init_tasks
    2017-05-18 20:36:00,076 INFO: Removing container: docker-puppet-keystone_init_tasks
    2017-05-18 20:36:00,384 DEBUG: docker-puppet-keystone_init_tasks
    
    2017-05-18 20:36:00,385 ERROR: ERROR configuring keystone_init_tasks
  deploy_stderr: |

Comment 1 Alexander Chuzhoy 2017-05-18 20:52:11 UTC

Created attachment 1280231 [details]
sosreport from controller

Comment 2 Dan Prince 2017-05-18 21:23:55 UTC

Could you check the contents of the keystone log. Should be in /var/log/containers/keystone/keystone.log. The patch to enable host logging landed recently though so if you don't have it yet you might have to login the the container itself and check the logs that way:
  docker exec -ti keystone /bin/bash
  cat /var/log/keystone/keystone.log


----

The logs will tell us more but just a guess is this a multi-controller setup? Or just a single controller. I'm wondering if perhaps the 'keystone-manage bootstrap' command might have failed for some reason.

We have an upstream patch that is fixing it so the bootstrap commands only execute on a single "bootstrap" host for each service. This could be related.

https://review.openstack.org/#/c/465551/

More info once we see the keystone logs here.

Comment 3 Alexander Chuzhoy 2017-05-18 21:26:56 UTC

Repeating error in /var/log/containers/keystone/keystone.log on controller:

2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi [req-439a5ba7-0497-4afc-ad1c-187825937ec7 - - - - -] None
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi Traceback (most recent call last):
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 374, in _inner
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi     return method(self, request)
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 431, in __call__
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi     response = self.process_request(request)
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/middleware/core.py", line 89, in process_request
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi     params_json = request.body
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 700, in _body__get
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi     self.make_body_seekable() # we need this to have content_length
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 942, in make_body_seekable
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi     self.copy_body()
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 959, in copy_body
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi     self._copy_body_tempfile()
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 973, in _copy_body_tempfile
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi     assert isinstance(todo, integer_types), todo
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi AssertionError: None
2017-05-18 21:26:17.627 25 ERROR keystone.common.wsgi 
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi [req-9a8845c4-3fdc-4fef-8df0-bba5fddf96ba - - - - -] None
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi Traceback (most recent call last):
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 374, in _inner
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi     return method(self, request)
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 431, in __call__
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi     response = self.process_request(request)
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/middleware/core.py", line 89, in process_request
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi     params_json = request.body
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 700, in _body__get
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi     self.make_body_seekable() # we need this to have content_length
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 942, in make_body_seekable
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi     self.copy_body()
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 959, in copy_body
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi     self._copy_body_tempfile()
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 973, in _copy_body_tempfile
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi     assert isinstance(todo, integer_types), todo
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi AssertionError: None
2017-05-18 21:26:19.631 24 ERROR keystone.common.wsgi 
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi [req-c84ebc32-a411-467c-abc3-f32cf8c54d43 - - - - -] None
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi Traceback (most recent call last):
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 374, in _inner
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi     return method(self, request)
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 431, in __call__
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi     response = self.process_request(request)
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/middleware/core.py", line 89, in process_request
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi     params_json = request.body
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 700, in _body__get
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi     self.make_body_seekable() # we need this to have content_length
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 942, in make_body_seekable
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi     self.copy_body()
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 959, in copy_body
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi     self._copy_body_tempfile()
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 973, in _copy_body_tempfile
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi     assert isinstance(todo, integer_types), todo
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi AssertionError: None
2017-05-18 21:26:19.631 23 ERROR keystone.common.wsgi 
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi [req-f49ed319-35b2-4150-a391-f813f45d0acb - - - - -] None
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi Traceback (most recent call last):
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 374, in _inner
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi     return method(self, request)
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 431, in __call__
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi     response = self.process_request(request)
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/middleware/core.py", line 89, in process_request
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi     params_json = request.body
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 700, in _body__get
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi     self.make_body_seekable() # we need this to have content_length
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 942, in make_body_seekable
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi     self.copy_body()
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 959, in copy_body
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi     self._copy_body_tempfile()
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 973, in _copy_body_tempfile
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi     assert isinstance(todo, integer_types), todo
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi AssertionError: None
2017-05-18 21:26:21.634 25 ERROR keystone.common.wsgi 
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi [req-eff4eba6-ddab-4805-9e9f-a9430e0cbb22 - - - - -] None
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi Traceback (most recent call last):
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 374, in _inner
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi     return method(self, request)
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 431, in __call__
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi     response = self.process_request(request)
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/middleware/core.py", line 89, in process_request
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi     params_json = request.body
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 700, in _body__get
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi     self.make_body_seekable() # we need this to have content_length
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 942, in make_body_seekable
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi     self.copy_body()
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 959, in copy_body
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi     self._copy_body_tempfile()
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 973, in _copy_body_tempfile
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi     assert isinstance(todo, integer_types), todo
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi AssertionError: None
2017-05-18 21:26:21.635 22 ERROR keystone.common.wsgi

Comment 4 Alexander Chuzhoy 2017-05-18 21:28:10 UTC

Checking in /var/log/keystone/keystone.log file in keystone container:

2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi [req-20125344-a151-4daf-b905-ae7ebe29aee4 - - - - -] None
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi Traceback (most recent call last):
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 374, in _inner
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi     return method(self, request)
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 431, in __call__
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi     response = self.process_request(request)
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/middleware/core.py", line 89, in process_request
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi     params_json = request.body
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 700, in _body__get
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi     self.make_body_seekable() # we need this to have content_length
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 942, in make_body_seekable
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi     self.copy_body()
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 959, in copy_body
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi     self._copy_body_tempfile()
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 973, in _copy_body_tempfile
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi     assert isinstance(todo, integer_types), todo
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi AssertionError: None
2017-05-18 21:27:33.789 23 ERROR keystone.common.wsgi 
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi [req-bec23c9c-709e-492a-8fc1-f88e0c226e21 - - - - -] None
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi Traceback (most recent call last):
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 374, in _inner
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi     return method(self, request)
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/common/wsgi.py", line 431, in __call__
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi     response = self.process_request(request)
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/keystone/middleware/core.py", line 89, in process_request
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi     params_json = request.body
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 700, in _body__get
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi     self.make_body_seekable() # we need this to have content_length
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 942, in make_body_seekable
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi     self.copy_body()
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 959, in copy_body
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi     self._copy_body_tempfile()
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi   File "/usr/lib/python2.7/site-packages/webob/request.py", line 973, in _copy_body_tempfile
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi     assert isinstance(todo, integer_types), todo
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi AssertionError: None
2017-05-18 21:27:33.789 25 ERROR keystone.common.wsgi

Comment 5 Dan Prince 2017-05-18 21:40:08 UTC

Could we reach out to the Keystone team on this one? Could be permissions or selinux related I suppose. Unclear if this is related directly to the containers.

Comment 6 Juan Antonio Osorio 2017-05-19 14:42:44 UTC

It is pretty cryptic. But I've seen this problem before if I mess up anything in the container template. So, one time when I wrote the volume section with a wrong syntax I saw this issue.

What would happen is that the container steps in Heat would keep running, and when it would get to that steps (which requires the keystone container to be up already) it would fail, since there would be no container yet.

Seems to be an issue of the container steps not reporting the error and stopping the deployment when they should.

Are other containers running? You could go to the overcloud controller and do docker ps to check what's there. If more are missing that keystone, it might be that what you tried to deploy had some error that docker-puppet didn't like.

Comment 7 Juan Antonio Osorio 2017-05-19 14:46:31 UTC

By the way, could you put the logs in a pastebin so they're easier to read?

Comment 8 Juan Antonio Osorio 2017-05-19 14:47:25 UTC

Also, how can I reproduce this?

Comment 9 Alexander Chuzhoy 2017-05-19 15:39:27 UTC

Juan,
to reproduce:
openstack overcloud deploy --templates --libvirt-type kvm -e /usr/share/openstack-tripleo-heat-templates/environments/docker.yaml -e /home/stack/templates/docker-osp12.yaml -e /home/stack/templates/nodes_data.yaml

Apply w/a for bugs encountered on the way:

bz #1451063
bz #1448482
bz #1452082
bz #1451491
bz #1450370

And you'll bump into this one.


What's missing from the attached sosreport?

Comment 10 Artem Hrechanychenko 2017-05-22 13:09:20 UTC

Hi all, 
any news about this issue?

Note You need to log in before you can comment on or make changes to this bug.