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/
After talking to aschultz, I think the fix should be in puppet-ironic.
According to our records, this should be resolved by puppet-ironic-9.5.0-3.el7ost. This build is available now.
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'],