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.
Created attachment 1345826 [details] undercloud upgrade log
Since this issue is related to Ironic I'm assigning this ticket to DFG:HardProv.
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.
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.
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
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...
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.
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).
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.
(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.
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
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.
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.
Backport upstream - https://review.openstack.org/#/c/517356/
*** Bug 1509969 has been marked as a duplicate of this bug. ***
The patch is not merged yet, moving back to ON_DEV
Correcting the project where the fix belongs.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2017:3231