Note: This is a beta release of Red Hat Bugzilla 5.0. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Also email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback here.
Bug 1510063 - Upgrade: potential problem with ACL of /var/log/ironic/ironic-dbsync.log
Summary: Upgrade: potential problem with ACL of /var/log/ironic/ironic-dbsync.log
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: puppet-ironic
Version: 10.0 (Newton)
Hardware: Unspecified
OS: Unspecified
urgent
urgent
Target Milestone: ---
: 10.0 (Newton)
Assignee: Dmitry Tantsur
QA Contact: mlammon
URL:
Whiteboard:
Depends On: 1507863
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-11-06 16:15 UTC by Dmitry Tantsur
Modified: 2018-03-22 13:26 UTC (History)
12 users (show)

Fixed In Version: puppet-ironic-9.5.0-3.el7ost
Doc Type: If docs needed, set a value
Doc Text:
Clone Of: 1507863
Environment:
Last Closed: 2018-03-22 13:26:32 UTC


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
OpenStack gerrit 518519 None None None 2017-11-11 21:05:40 UTC

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'],


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