Bug 1510063

Summary: Upgrade: potential problem with ACL of /var/log/ironic/ironic-dbsync.log
Product: Red Hat OpenStack Reporter: Dmitry Tantsur <dtantsur>
Component: puppet-ironicAssignee: Dmitry Tantsur <dtantsur>
Status: CLOSED CURRENTRELEASE QA Contact: mlammon
Severity: urgent Docs Contact:
Priority: urgent    
Version: 10.0 (Newton)CC: bfournie, dbecker, jjoyce, jschluet, mburns, mcornea, morazi, nlevinki, rhel-osp-director-maint, slinaber, tvignaud, yprokule
Target Milestone: ---Keywords: TestOnly, Triaged, ZStream
Target Release: 10.0 (Newton)   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: puppet-ironic-9.5.0-3.el7ost Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1507863 Environment:
Last Closed: 2018-03-22 13:26:32 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1507863    
Bug Blocks:    

Description Dmitry Tantsur 2017-11-06 16:15:30 UTC 
The same problem must be affecting


+++ This bug was initially created as a clone of Bug #1507863 +++

Description of problem:
OSP9 -> OSP10: undercloud upgrade fails: mError: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns: change from notrun to 0 failed: ironic-dbsync --config-file /etc/ironic/ironic.conf  returned 1 instead of one of [0]:


snippet from the log:

2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns: Option "rpc_backend" from group "DEFAULT" is deprecated for removal.  Its value may be silently ignored in the future.ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns: Traceback (most recent call last):ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/bin/ironic-dbsync", line 10, in <module>ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     sys.exit(main())ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib/python2.7/site-packages/ironic/cmd/dbsync.py", line 102, in mainESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     service.prepare_service(sys.argv)ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib/python2.7/site-packages/ironic/common/service.py", line 47, in prepare_serviceESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     log.setup(CONF, 'ironic')ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib/python2.7/site-packages/oslo_log/log.py", line 269, in setupESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     _setup_logging_from_conf(conf, product_name, version)ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib/python2.7/site-packages/oslo_log/log.py", line 366, in _setup_logging_from_confESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     filelog = file_handler(logpath)ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib64/python2.7/logging/handlers.py", line 392, in __init__ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     logging.FileHandler.__init__(self, filename, mode, encoding, delay)ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     StreamHandler.__init__(self, self._open())ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _openESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     stream = open(self.baseFilename, self.mode)ESC[0m
2017-10-31 06:41:26 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns: IOError: [Errno 13] Permission denied: '/var/log/ironic/ironic-dbsync.log'ESC[0m
2017-10-31 06:41:26 - ESC[1;31mError: ironic-dbsync --config-file /etc/ironic/ironic.conf  returned 1 instead of one of [0]ESC[0m
2017-10-31 06:41:26 - ESC[1;31mError: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns: change from notrun to 0 failed: ironic-dbsync --config-file /etc/ironic/ironic.conf  returned 1 instead of one of [0]ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns: Option "rpc_backend" from group "DEFAULT" is deprecated for removal.  Its value may be silently ignored in the future.ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns: Traceback (most recent call last):ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/bin/ironic-dbsync", line 10, in <module>ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     sys.exit(main())ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib/python2.7/site-packages/ironic/cmd/dbsync.py", line 102, in mainESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     service.prepare_service(sys.argv)ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib/python2.7/site-packages/ironic/common/service.py", line 47, in prepare_serviceESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     log.setup(CONF, 'ironic')ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib/python2.7/site-packages/oslo_log/log.py", line 269, in setupESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     _setup_logging_from_conf(conf, product_name, version)ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib/python2.7/site-packages/oslo_log/log.py", line 366, in _setup_logging_from_confESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     filelog = file_handler(logpath)ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib64/python2.7/logging/handlers.py", line 392, in __init__ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     logging.FileHandler.__init__(self, filename, mode, encoding, delay)ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib64/python2.7/logging/__init__.py", line 902, in __init__ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     StreamHandler.__init__(self, self._open())ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:   File "/usr/lib64/python2.7/logging/__init__.py", line 925, in _openESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns:     stream = open(self.baseFilename, self.mode)ESC[0m
2017-10-31 06:42:24 - ESC[mNotice: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]/returns: IOError: [Errno 13] Permission denied: '/var/log/ironic/ironic-dbsync.log'ESC[0m
2017-10-31 06:42:24 - ESC[1;31mError: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]: Failed to call refresh: ironic-dbsync --config-file /etc/ironic/ironic.conf  returned 1 instead of one of [0]ESC[0m
2017-10-31 06:42:24 - ESC[1;31mError: /Stage[main]/Ironic::Db::Sync/Exec[ironic-dbsync]: ironic-dbsync --config-file /etc/ironic/ironic.conf  returned 1 instead of one of [0]ESC[0m


[stack@undercloud-0 ~]$ ls -l /var/log/ironic/ironic-dbsync.log
ls: cannot access /var/log/ironic/ironic-dbsync.log: Permission denied

[stack@undercloud-0 ~]$ sudo ls -l /var/log/ironic/ironic-dbsync.log
-rw-r--r--. 1 root root 0 Oct 31 05:45 /var/log/ironic/ironic-dbsync.log

Version-Release number of selected component (if applicable):
[stack@undercloud-0 ~]$ rpm -qa | grep puppet-modules
openstack-puppet-modules-9.3.0-1.el7ost.noarch
[stack@undercloud-0 ~]$ rpm -qa | grep ironic
puppet-ironic-9.5.0-2.el7ost.noarch
openstack-ironic-api-6.2.4-2.el7ost.noarch
python-ironic-lib-2.1.3-1.el7ost.noarch
openstack-ironic-inspector-4.2.2-3.el7ost.noarch
python-ironicclient-1.7.1-1.el7ost.noarch
openstack-ironic-common-6.2.4-2.el7ost.noarch
openstack-ironic-conductor-6.2.4-2.el7ost.noarch
python-ironic-tests-6.2.4-2.el7ost.noarch
python-ironic-inspector-client-1.10.0-1.el7ost.noarch


How reproducible:
100%

Steps to Reproduce:
1. Deploy OSP9
2. Upgrade undercloud to OSP10

Actual results:
Undercloud upgrade fails.

Expected results:
Undercloud upgrade succeeds.

Additional info:
Attaching the undercloud upgrade log.

--- snip ---

--- Additional comment from Bob Fournier on 2017-10-31 08:11:17 EDT ---

Thanks Marius. On first glance - as you've seen too - it looks like a permission issue trying to open /var/log/ironic/ironic-dbsync.log by ironic-dbsync.   I see that the permissions look OK when you've checked.

[stack@undercloud-0 ~]$ sudo ls -l /var/log/ironic/ironic-dbsync.log
-rw-r--r--. 1 root root 0 Oct 31 05:45 /var/log/ironic/ironic-dbsync.log

But any idea what they were set to in OSP-9?  I'm wondering if they were not correct when ironic-dbsync ran.

--- Additional comment from Bob Fournier on 2017-10-31 09:25:25 EDT ---

So it looks like this change that makes /var/log/ironic no longer world readable may have landed in this OSP-10z release - https://review.rdoproject.org/r/#/c/9683/ (I'll confirm that).  I wonder if this has any affect to the problem of not being able to open /var/log/ironic/ironic-dbsync.log.

--- Additional comment from Marius Cornea on 2017-10-31 09:44:17 EDT ---

Checking the permissions during OSP9 deployment:

[root@undercloud-0 ~]# ls -l /var/log/ironic/
total 540
-rw-r--r--. 1 ironic ironic 275176 Oct 31 09:41 ironic-api.log
-rw-r--r--. 1 ironic ironic  26328 Oct 31 09:39 ironic-conductor.log
-rw-r--r--. 1 root   root        0 Oct 31 09:18 ironic-dbsync.log

--- Additional comment from Bob Fournier on 2017-10-31 10:15:33 EDT ---

Thanks Marius. So yeah, the dir /var/log/ironic was world readable in OSP9 and made not world readable when going to OSP-10.  That appears to be causing a problem with permissions when ironic-dbsync attempts to open /var/log/ironic/ironic-dbsync.log. Still looking...

--- Additional comment from Bob Fournier on 2017-10-31 10:59:09 EDT ---

Marius - one more thing, can you add the /etc/ironic/ironic.conf you are using to this bug? Thanks.

And yes, the fix for https://bugzilla.redhat.com/show_bug.cgi?id=1431468 which made /var/log/ironic not world readable is also in this puddle.

--- Additional comment from Bob Fournier on 2017-10-31 14:15:15 EDT ---

Note its actually this BZ that is also fixed in the puddle - https://bugzilla.redhat.com/show_bug.cgi?id=1431479
(and may be potentially be the source of the problem).

--- Additional comment from Bob Fournier on 2017-10-31 15:54:11 EDT ---

Marius, can you try one thing - delete /var/log/ironic-dbsync.log prior to the
upgrade, then upgrade?  Since ironic-dbsync.log is owned by root in OSP-9 I wonder if it can't be accessed by the "ironic" user in OSP-10.

--- Additional comment from Marius Cornea on 2017-11-01 05:54:31 EDT ---

(In reply to Bob Fournier from comment #10)
> Marius, can you try one thing - delete /var/log/ironic-dbsync.log prior to
> the
> upgrade, then upgrade?  Since ironic-dbsync.log is owned by root in OSP-9 I
> wonder if it can't be accessed by the "ironic" user in OSP-10.

Yes, deleting /var/log/ironic/ironic-dbsync.log before running the undercloud upgrade allows it to move forward.

--- Additional comment from Bob Fournier on 2017-11-01 08:43:25 EDT ---

Thanks Marius.

So it looks like an issue with the file owner, not the directory change that was made by https://bugzilla.redhat.com/show_bug.cgi?id=1431479.

In OSP-9, the file is owned by root, on the upgrade ironic-dbsync runs as ironic user and fails.
-rw-r--r--. 1 root   root   0 Oct 31 09:18 ironic-dbsync.log

when its created in osp-10 its owned by ironic
-rw-r--r--. 1 ironic ironic 0 Nov  1 07:08 ironic-dbsync.log

--- Additional comment from Dmitry Tantsur on 2017-11-01 12:20:53 EDT ---

I think this was caused by the following commit: https://github.com/openstack/puppet-ironic/commit/bf00e679016b60b421a9af353dd09dcaef514926#diff-5106a5beab0a246889a8cf98d3d992d0. It does not take upgrades into account. I believe it has to be fixed in puppet-ironic, but I'd double-check with someone from the puppet team.

--- Additional comment from Bob Fournier on 2017-11-02 09:19:35 EDT ---

So it looks like this file ownership problem has been fixed in OSP-12 and OSP-11 -https://review.openstack.org/#/c/459871/2/instack_undercloud/undercloud.py
but the fix hasn't been backported to OSP-10.

I will add a backport to OSP-10.

--- Additional comment from Bob Fournier on 2017-11-02 12:01:20 EDT ---

Backport upstream - https://review.openstack.org/#/c/517356/
Comment 1 Dmitry Tantsur 2017-11-06 16:43:56 UTC 
After talking to aschultz, I think the fix should be in puppet-ironic.
Comment 3 Lon Hohberger 2018-03-07 13:51:33 UTC 
According to our records, this should be resolved by puppet-ironic-9.5.0-3.el7ost.  This build is available now.
Comment 4 mlammon 2018-03-13 19:10:33 UTC 
On latest osp10 install we see the resolution in the code. We also have confidence its covered in other osp9->osp10 upgrade test. Marking verified.  


Environment
[root@undercloud-0 ~]# rpm -qa | grep puppet-ironic-9.5.0-3.el7ost
puppet-ironic-9.5.0-3.el7ost.noarch



[root@undercloud-0 usr]# sudo more ./share/openstack-puppet/modules/ironic/manifests/db/sync.pp
#
# Class to execute ironic dbsync
#
# == Parameters
#
# [*extra_params*]
#   (optional) String of extra command line parameters to append
#   to the ironic-dbsync command.
#   Defaults to undef
#
class ironic::db::sync(
  $extra_params  = undef,
) {

  include ::ironic::deps
  include ::ironic::params

  # NOTE(dtantsur): previous ironic-dbsync was run as root. it will fail to run
  # as "ironic" user, if there is an old log file owned by root. Let's fix it.
  # To be removed in Rocky.
  file { '/var/log/ironic/ironic-dbsync.log':
    ensure  => 'present',
    owner   => 'ironic',
    group   => 'ironic',
    # /var/log/ironic comes from ironic-common
    require => Anchor['ironic::install::end']
  }

  exec { 'ironic-dbsync':
    command     => "${::ironic::params::dbsync_command} ${extra_params}",
    path        => '/usr/bin',
    user        => 'ironic',
    refreshonly => true,
    try_sleep   => 5,
    tries       => 10,
    logoutput   => on_failure,
    subscribe   => [
      Anchor['ironic::install::end'],
      Anchor['ironic::config::end'],
      Anchor['ironic::dbsync::begin']
    ],
    notify      => Anchor['ironic::dbsync::end'],