Bug 1174795

Created attachment 969554 [details]
keystone.pp.log

Created attachment 969555 [details]
/var/log/messages

Another report of the same bug:
https://bugs.launchpad.net/openstack-community/+bug/1351357

First thing to ensure is that there is only the packaged python-oslo-config installed on the system. I.E. no pip installed, or devstack installed version.
The reason is that python-oslo-config is patched to look for /usr/share/keystone/keystone-dist.conf as per http://pkgs.fedoraproject.org/cgit/python-oslo-config.git/tree/0001-add-usr-share-project-dist.conf-to-the-default-confi.patch

And it's that config that links to the correct /usr/share/keystone/keystone-dist-paste.ini

The other thing to consider is the precedence detailed in the link above,
where it says that settings in /etc/keystone/keystone.conf will override those in the dist config in user share. So that would be an issue if packstack for example was setting the value to the default keystone-paste.ini

devstack should not be an issue because I'm starting from a freshly
installed VM.  Also I have checked that it is not installed.

pip is installed, no idea where/what installed it (but it was not me):

python3-pip-1.5.6-4.fc22.noarch

Here are the oslo-related packages installed after the packstack run:

python-oslo-i18n-1.1.0-1.fc22.noarch
python-oslo-config-1.4.0-1.fc22.noarch
python-oslo-utils-1.0.0-1.fc22.noarch
python-oslo-messaging-1.4.1-2.fc22.noarch
python-oslo-db-1.0.2-2.fc22.noarch

I manually checked /usr/lib/python2.7/site-packages/oslo/config/cfg.py
and it has the precise patch that you mention in comment 4.

/etc/keystone/keystone.conf (after running packstack) has this
section:

-------------------
[paste_deploy]

#
# Options defined in keystone
#

# Name of the paste configuration file that defines the
# available pipelines. (string value)
#config_file=/usr/share/keystone/keystone-dist-paste.ini
-------------------

The overall file does have changes:

$ sudo rpm -V openstack-keystone
.....U...    /etc/keystone
SM5..U.T.  c /etc/keystone/keystone.conf
.M.......    /var/lib/keystone

I will see if I can make rpm come up with a diff ...

Created attachment 970172 [details]
keystone.conf.diff

Differences between RPM-installed /etc/keystone/keystone.conf
and the final version of this file after (presumably) modifications
by Packstack.

The config all looks OK TBH. The next step I would use is to add debugging to /usr/lib/python2.7/site-packages/oslo/config/cfg.py to see if it's picking up /usr/share/keystone/keystone-dist.conf The symptoms suggest that's being ignored for some reason

    config_files = []
    if project:
        config_files.append(_search_dirs(['/usr/share/%s/' % project],
                                         project, '-dist%s' % extension))
        config_files.append(_search_dirs(['/usr/share/%s/' % project],
                                         prog, '-dist%s' % extension))
        config_files.append(_search_dirs(cfg_dirs, project, extension))
    config_files.append(_search_dirs(cfg_dirs, prog, extension))

    ### HERE:
    ### project = keystone
    ### prog = keystone-all
    ### config_files = [None, None, '/etc/keystone/keystone.conf', None]

    return list(moves.filter(bool, config_files))

This function is called 5 times in all for a single start-up, and
displays the same values each time.

It looks wrong to me since:

$ ls -1 /usr/share/keystone/
keystone-dist.conf
keystone-dist-paste.ini
keystone.wsgi
policy.v3cloudsample.json
sample_data.sh
wsgi-keystone.conf

I would expect /usr/share/keystone/keystone-dist.conf to be returned.

I added some debug to _search_dirs, but strangely it looks as if
os.path.exists ("/usr/share/keystone/keystone-dist.conf") ==> false.
Wut?

I added debugging into find_file / _search_dirs:

 FIND_FILE name = keystone-paste.ini
 CHECKING path = /etc/keystone/keystone-paste.ini
 CHECKING path = /var/lib/keystone/.keystone/keystone-paste.ini
 CHECKING path = /var/lib/keystone/keystone-paste.ini
 CHECKING path = /etc/keystone/keystone-paste.ini
 CHECKING path = /etc/keystone-paste.ini
 paste_config = None
 (failure happens immediately after this)

/var/lib/keystone is empty.  There's no file on the whole machine
called 'keystone-paste.ini'.  The nearest one as mentioned previously
is '/usr/share/keystone/keystone-dist-paste.ini'

No idea what to make of this.

OK, turns out to be an SELinux issue (thanks Padraig/Alan).

With SELinux set to Permissive, keystone is able to start up.

type=AVC msg=audit(1418833963.580:1474): avc:  denied  { getattr } for  pid=15900 comm="keystone-all" path="/usr/share/keystone/keystone-dist.conf" dev="sda1" ino=925373 scontext=system_u:system_r:keystone_t:s0 tcontext=system_u:object_r:keystone_cgi_script_exec_t:s0 tclass=file permissive=1
type=AVC msg=audit(1418833963.580:1475): avc:  denied  { read } for  pid=15900 comm="keystone-all" name="keystone-dist.conf" dev="sda1" ino=925373 scontext=system_u:system_r:keystone_t:s0 tcontext=system_u:object_r:keystone_cgi_script_exec_t:s0 tclass=file permissive=1
type=AVC msg=audit(1418833963.580:1476): avc:  denied  { open } for  pid=15900 comm="keystone-all" path="/usr/share/keystone/keystone-dist.conf" dev="sda1" ino=925373 scontext=system_u:system_r:keystone_t:s0 tcontext=system_u:object_r:keystone_cgi_script_exec_t:s0 tclass=file permissive=1

This happens also with x86_64 arch.

I almost created a duplicated bug:

Description of problem:
keystone fails to start as stand-alone service (This how packstack-2014.2-0.13.dev1395.gaabe0a2.fc22) tries to install it.

Version-Release number of selected component (if applicable):

openstack-keystone-2014.2.1-1.fc22
python-keystone-2014.2.1-1.fc22
selinux-policy-3.13.1-103.fc21
libselinux-2.3-5.fc21

How reproducible:
always

Steps to Reproduce:
Boot f21 20141203 cloud image.

$ sudo yum update -y
$ sudo yum install -y https://rdo.fedorapeople.org/rdo-release.rpm
$ sudo yum install -y openstack-packstack
$ packstack --allinone


Actual results:

172.16.40.44_keystone.pp:                         [ ERROR ]         
Applying Puppet manifests                         [ ERROR ]

ERROR : Error appeared during Puppet run: 172.16.40.44_keystone.pp
Error: Could not start Service[keystone]: Execution of '/sbin/service openstack-keystone start' returned 1: Redirecting to /bin/systemctl start  openstack-keystone.service
You will find full trace in log /var/tmp/packstack/20150108-085019-XoEQKa/manifests/172.16.40.44_keystone.pp.log
Please check log file /var/tmp/packstack/20150108-085019-XoEQKa/openstack-setup.log for more information


$ journalctl -u openstack-keystone
Jan 08 08:54:52 afazekas-f21-rdo-2 keystone-all[10618]: 2015-01-08 08:54:52.897 10618 CRITICAL keystone [-] ConfigFileNotFound: An unexpected error prevented the server from fulfilling your request.
Jan 08 08:54:52 afazekas-f21-rdo-2 keystone-all[10618]: 2015-01-08 08:54:52.897 10618 TRACE keystone Traceback (most recent call last):
Jan 08 08:54:52 afazekas-f21-rdo-2 keystone-all[10618]: 2015-01-08 08:54:52.897 10618 TRACE keystone   File "/usr/bin/keystone-all", line 134, in <module>
Jan 08 08:54:52 afazekas-f21-rdo-2 keystone-all[10618]: 2015-01-08 08:54:52.897 10618 TRACE keystone     paste_config = config.find_paste_config()
Jan 08 08:54:52 afazekas-f21-rdo-2 keystone-all[10618]: 2015-01-08 08:54:52.897 10618 TRACE keystone   File "/usr/lib/python2.7/site-packages/keystone/config.py", line 90, in find_paste_config
Jan 08 08:54:52 afazekas-f21-rdo-2 keystone-all[10618]: 2015-01-08 08:54:52.897 10618 TRACE keystone     raise exception.ConfigFileNotFound(config_file=paste_config_value)
Jan 08 08:54:52 afazekas-f21-rdo-2 keystone-all[10618]: 2015-01-08 08:54:52.897 10618 TRACE keystone ConfigFileNotFound: An unexpected error prevented the server from fulfilling your request.
Jan 08 08:54:52 afazekas-f21-rdo-2 keystone-all[10618]: 2015-01-08 08:54:52.897 10618 TRACE keystone
Jan 08 08:54:52 afazekas-f21-rdo-2 systemd[1]: openstack-keystone.service: main process exited, code=exited, status=1/FAILURE

$ ls -lZ /usr/share/keystone/keystone-dist-paste.ini 
-rw-r--r--. root keystone system_u:object_r:keystone_cgi_script_exec_t:s0 /usr/share/keystone/keystone-dist-paste.ini
$ ls -ldZ /usr/share/keystone
drwxr-xr-x. root root system_u:object_r:keystone_cgi_script_exec_t:s0 /usr/share/keystone

$ audit2allow  -v </var/log/audit/audit.log 
#============= keystone_t ==============
# src="keystone_t" tgt="keystone_cgi_script_exec_t" class="dir", perms="search"
# comm="keystone-all" exe="" path=""
allow keystone_t keystone_cgi_script_exec_t:dir search;

In permissive mode you can see additional policies would be violated:

$ setenforce 0
$ service openstack-keystone start
Redirecting to /bin/systemctl start  openstack-keystone.service
$  audit2allow  -v </var/log/audit/audit.log 

#============= keystone_t ==============
# src="keystone_t" tgt="keystone_cgi_script_exec_t" class="dir", perms="search"
# comm="keystone-all" exe="" path=""
allow keystone_t keystone_cgi_script_exec_t:dir search;
# src="keystone_t" tgt="keystone_cgi_script_exec_t" class="file", perms="{ read getattr open }"
# comm="keystone-all" exe="" path=""
allow keystone_t keystone_cgi_script_exec_t:file { read getattr open };

Expected results:
Keystone is able to work as stand-alne service with selinux in Enforcing mode.

Additional info:
I did not tried with mod_wsgi yet.

i also hit this trying instack-install-undercloud [1] - trace looks like [2] as above. This is on rhel 7.0 and using rhos-release to enable the latest rhelosp repo

After I setenforce0 this issue is resolved.

[1] https://openstack.redhat.com/Deploying_an_RDO_Undercloud_with_Instack

[2] 
Jan  8 05:45:29 localhost systemd: Starting OpenStack Identity Service (code-named Keystone)...
Jan  8 05:45:30 localhost ceilometer-api: /usr/lib/python2.7/site-packages/pecan/__init__.py:110: RuntimeWarning: `static_root` is only used when `debug` is True, ignoring
Jan  8 05:45:30 localhost ceilometer-api: RuntimeWarning
Jan  8 05:45:31 localhost keystone-all: 2015-01-08 05:45:30.998 29896 CRITICAL keystone [-] ConfigFileNotFound: An unexpected error prevented the server from fulfilling your request.
Jan  8 05:45:31 localhost keystone-all: 2015-01-08 05:45:30.998 29896 TRACE keystone Traceback (most recent call last):
Jan  8 05:45:31 localhost keystone-all: 2015-01-08 05:45:30.998 29896 TRACE keystone   File "/usr/bin/keystone-all", line 134, in <module>
Jan  8 05:45:31 localhost keystone-all: 2015-01-08 05:45:30.998 29896 TRACE keystone     paste_config = config.find_paste_config()
Jan  8 05:45:31 localhost keystone-all: 2015-01-08 05:45:30.998 29896 TRACE keystone   File "/usr/lib/python2.7/site-packages/keystone/config.py", line 90, in find_paste_config
Jan  8 05:45:31 localhost keystone-all: 2015-01-08 05:45:30.998 29896 TRACE keystone     raise exception.ConfigFileNotFound(config_file=paste_config_value)

type=AVC msg=audit(1418833963.580:1474): avc:  denied  { getattr } for  pid=15900 comm="keystone-all" path="/usr/share/keystone/keystone-dist.conf" dev="sda1" ino=925373 scontext=system_u:system_r:keystone_t:s0 tcontext=system_u:object_r:keystone_cgi_script_exec_t:s0 tclass=file permissive=1

	Was caused by:
		Unknown - would be allowed by active policy
		Possible mismatch between this policy and the one under which the audit message was generated.

		Possible mismatch between current in-memory boolean settings vs. permanent ones.

type=AVC msg=audit(1418833963.580:1475): avc:  denied  { read } for  pid=15900 comm="keystone-all" name="keystone-dist.conf" dev="sda1" ino=925373 scontext=system_u:system_r:keystone_t:s0 tcontext=system_u:object_r:keystone_cgi_script_exec_t:s0 tclass=file permissive=1

	Was caused by:
		Unknown - would be allowed by active policy
		Possible mismatch between this policy and the one under which the audit message was generated.

		Possible mismatch between current in-memory boolean settings vs. permanent ones.

type=AVC msg=audit(1418833963.580:1476): avc:  denied  { open } for  pid=15900 comm="keystone-all" path="/usr/share/keystone/keystone-dist.conf" dev="sda1" ino=925373 scontext=system_u:system_r:keystone_t:s0 tcontext=system_u:object_r:keystone_cgi_script_exec_t:s0 tclass=file permissive=1

	Was caused by:
		Unknown - would be allowed by active policy
		Possible mismatch between this policy and the one under which the audit message was generated.

		Possible mismatch between current in-memory boolean settings vs. permanent ones.