Bug 1707099 - Unable to login to OC BM instance booted with overcloud-full image with cloud-user.
Summary: Unable to login to OC BM instance booted with overcloud-full image with cloud...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-tripleo-heat-templates
Version: 15.0 (Stein)
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: beta
: 15.0 (Stein)
Assignee: Bob Fournier
QA Contact: Alexander Chuzhoy
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-05-06 19:47 UTC by Alexander Chuzhoy
Modified: 2019-10-22 12:53 UTC (History)
14 users (show)

Fixed In Version: openstack-tripleo-heat-templates-10.5.1-0.20190528190414.f41e7e4.1.el8ost
Doc Type: No Doc Update
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-09-21 11:21:45 UTC
Target Upstream Version:


Attachments (Terms of Use)
cloud-init log (16.05 KB, application/gzip)
2019-05-10 19:07 UTC, Alexander Chuzhoy
no flags Details


Links
System ID Private Priority Status Summary Last Updated
OpenStack gerrit 661023 0 None MERGED Set force_config_drive only when OVNMetadata is disabled 2020-07-31 08:58:07 UTC
Red Hat Product Errata RHEA-2019:2811 0 None None None 2019-09-21 11:21:56 UTC

Description Alexander Chuzhoy 2019-05-06 19:47:23 UTC
Unable to login to OC BM instance booted with overcloud-full image with cloud-user.

Environment:
python3-ironic-lib-2.16.2-0.20190312184129.2020575.el8ost.noarch
puppet-ironic-14.4.1-0.20190420120354.f4220d1.el8ost.noarch
openstack-ironic-api-12.1.1-0.20190420011811.98a9730.el8ost.noarch
python3-ironicclient-2.7.0-0.20190312102843.4af8a79.el8ost.noarch
python3-ironic-inspector-client-3.5.0-0.20190313131319.9bb1150.el8ost.noarch
openstack-ironic-common-12.1.1-0.20190420011811.98a9730.el8ost.noarch



Steps to reproduce:

Deploy OC with BMaaS.
Boot BM instances with the same image used to deploy OC with these commands:


openstack keypair create --public-key ~/.ssh/id_rsa.pub stack-key
openstack server create --image overcloud-full --flavor baremetal --nic net-id=$(openstack network show baremetal -f value -c id) --key-name stack-key bmserver1


Wait until the server is up.

Try to ssh into the machine with cloud-user.


Result:

(undercloud) [stack@undercloud-0 ~]$ ssh cloud-user@192.168.24.74
Warning: Permanently added '192.168.24.74' (ECDSA) to the list of known hosts.
cloud-user@192.168.24.74: Permission denied (publickey,gssapi-keyex,gssapi-with-mic).



Logged into the image via root user and saw that the .ssh/authorized_keys file is empty for cloud-user. The user did exist on the instance.

Comment 1 Alexander Chuzhoy 2019-05-06 19:48:32 UTC
On the same setup I booted a regular instance with cirros image and was able to login with cirros user using the public key provided with --key-name.

Comment 3 Bob Fournier 2019-05-10 13:19:55 UTC
Sasha - on the instance we should see cloud-init adding the cloud-user, for example (on another system):

[cloud-user@instance1 log]$ sudo grep cloud-user /var/log/cloud-init.log
2019-04-10 20:28:41,370 - __init__.py[DEBUG]: Adding user cloud-user
2019-04-10 20:28:41,371 - util.py[DEBUG]: Running hidden command to protect sensitive input/output logstring: ['useradd', 'cloud-user', '--comment', 'Cloud User', '--groups', 'adm,systemd-journal,wheel', '--shell', '/bin/bash', '-m']
2019-04-10 20:28:41,481 - util.py[DEBUG]: Running command ['passwd', '-l', 'cloud-user'] with allowed return codes [0] (shell=False, capture=True)
2019-04-10 20:28:41,565 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user (recursive=True)
2019-04-10 20:28:41,567 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=False)
2019-04-10 20:28:41,567 - util.py[DEBUG]: Changing the ownership of /home/cloud-user/.ssh to 1000:1001
2019-04-10 20:28:41,580 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=True)
2019-04-10 20:28:41,581 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=False)
2019-04-10 20:28:41,582 - util.py[DEBUG]: Writing to /home/cloud-user/.ssh/authorized_keys - wb: [384] 433 bytes
2019-04-10 20:28:41,583 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh/authorized_keys (recursive=False)
2019-04-10 20:28:41,584 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh/authorized_keys (recursive=False)
2019-04-10 20:28:41,584 - util.py[DEBUG]: Changing the ownership of /home/cloud-user/.ssh/authorized_keys to 1000:1001
2019-04-10 20:28:41,585 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=True)
2019-04-10 20:28:44,462 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=True)
2019-04-10 20:28:44,463 - util.py[DEBUG]: Reading from /home/cloud-user/.ssh/authorized_keys (quiet=False)
2019-04-10 20:28:44,463 - util.py[DEBUG]: Read 433 bytes from /home/cloud-user/.ssh/authorized_keys

When you're logged in as root can retrieve /var/log/cloud-init.log?  If you can't get this file can you check if the cloud-init pkg is installed?

Comment 4 Alexander Chuzhoy 2019-05-10 19:07:56 UTC
Created attachment 1566779 [details]
cloud-init log

Comment 5 Bob Fournier 2019-05-10 19:36:39 UTC
On sasha's system, looks like the cloud-user is being set up fine but 0 bytes are written to /home/cloud-user/.ssh/authorized_keys.

[root@host-192-168-24-97 ~]# grep cloud-user /var/log/cloud-init.log
2019-05-10 18:46:09,239 - __init__.py[DEBUG]: Adding user cloud-user
2019-05-10 18:46:09,239 - util.py[DEBUG]: Running hidden command to protect sensitive input/output logstring: ['useradd', 'cloud-user', '--comment', 'Cloud User', '--groups', 'adm,systemd-journal,wheel', '--shell', '/bin/bash', '-m']
2019-05-10 18:46:09,637 - util.py[DEBUG]: Running command ['passwd', '-l', 'cloud-user'] with allowed return codes [0] (shell=False, capture=True)
2019-05-10 18:46:09,658 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user (recursive=True)
2019-05-10 18:46:09,660 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=False)
2019-05-10 18:46:09,660 - util.py[DEBUG]: Changing the ownership of /home/cloud-user/.ssh to 1000:1001
2019-05-10 18:46:09,661 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=True)
2019-05-10 18:46:09,662 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=False)
2019-05-10 18:46:09,662 - util.py[DEBUG]: Writing to /home/cloud-user/.ssh/authorized_keys - wb: [600] 0 bytes  <======
2019-05-10 18:46:09,662 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh/authorized_keys (recursive=False)
2019-05-10 18:46:09,663 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh/authorized_keys (recursive=False)
2019-05-10 18:46:09,663 - util.py[DEBUG]: Changing the ownership of /home/cloud-user/.ssh/authorized_keys to 1000:1001
2019-05-10 18:46:09,663 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=True)
2019-05-10 18:46:11,003 - util.py[DEBUG]: Restoring selinux mode for /home/cloud-user/.ssh (recursive=True)
2019-05-10 18:46:11,004 - util.py[DEBUG]: Reading from /home/cloud-user/.ssh/authorized_keys (quiet=False)
2019-05-10 18:46:11,004 - util.py[DEBUG]: Read 0 bytes from /home/cloud-user/.ssh/authorized_keys  <=====

Comment 6 Bob Fournier 2019-05-10 19:44:41 UTC
Looks like an issue getting metadata for sasha's instance:
loud-init-output.log:2019-05-10 18:45:49,439 - url_helper.py[WARNING]: Calling 'http://192.168.24.1/latest/meta-data/instance-id' failed [101/120s]: request error [HTTPConnectionPool(host='192.168.24.1', port=80): Max retries exceeded with url: /latest/meta-data/instance-id (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7f28a44d8390>, 'Connection to 192.168.24.1 timed out. (connect timeout=50.0)'))]
cloud-init-output.log:2019-05-10 18:46:07,460 - url_helper.py[WARNING]: Calling 'http://192.168.24.1/latest/meta-data/instance-id' failed [119/120s]: request error [HTTPConnectionPool(host='192.168.24.1', port=80): Max retries exceeded with url: /latest/meta-data/instance-id (Caused by ConnectTimeoutError(<urllib3.connection.HTTPConnection object at 0x7f28a44d8ba8>, 'Connection to 192.168.24.1 timed out. (connect timeout=17.0)'))]

Comment 7 Bob Fournier 2019-05-10 20:14:55 UTC
Also there's no route to the metadata server 169.254.169.254
[root@host-192-168-24-97 ~]# ip route
default via 192.168.24.1 dev eth0 proto dhcp metric 100 
192.168.24.0/24 dev eth0 proto kernel scope link src 192.168.24.97 metric 100

versus what we see on working instance on osp-13:
cloud-user@instance1 ~]$ ip route
default via 172.21.2.1 dev em1 proto dhcp metric 100 
169.254.169.254 via 172.21.2.1 dev em1 proto dhcp metric 100 
172.21.2.0/24 dev em1 proto kernel scope link src 172.21.2.206 metric 100

Comment 8 Dmitry Tantsur 2019-05-13 09:33:01 UTC
We should use configdrive, not metadata. I wonder if something has changed that prevented configdrives from being read.

Comment 9 Derek Higgins 2019-05-16 15:54:51 UTC
Sasha - 
Can you log onto the instance, mount the config-drive (it should be a 64M partition) and see if the files in there contain your key.
Also can you take a look at ~/.ssh/id_rsa.pub to make sure it isn't an empty file for some reason.

Comment 10 Alexander Chuzhoy 2019-05-17 17:04:26 UTC
So if the server is created with "--config-drive true" - the issue doesn't reproduce.

Comment 11 Bob Fournier 2019-05-17 17:11:45 UTC
Thanks for testing Sasha.  Derek found that force_config_drive is set to false in OSP-15 where previously it was true, this is because of the ovn change https://review.opendev.org/#/c/502943/.  The release note for this change indicates:
features:
  - Adds ability to configure metadata agent for networking-ovn based deployments.
upgrade:
  - force_config_drive is now set to False in Nova. Instances will now fetch their metadata from the metadata service instead from the config drive.


Using the metadata service isn't working properly...

Comment 12 Alexander Chuzhoy 2019-05-17 19:09:54 UTC
During boot the BM instance's console shows:
[   45.726833] cloud-init[1072]: 2019-05-17 19:08:55,628 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [7/120s]: bad status code [404]
[   47.777999] cloud-init[1072]: 2019-05-17 19:08:57,679 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [9/120s]: bad status code [404]
[   49.833946] cloud-init[1072]: 2019-05-17 19:08:59,735 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [11/120s]: bad status code [404]
[   51.884542] cloud-init[1072]: 2019-05-17 19:09:01,785 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [13/120s]: bad status code [404]
[   53.931933] cloud-init[1072]: 2019-05-17 19:09:03,833 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [15/120s]: bad status code [404]
[   56.997295] cloud-init[1072]: 2019-05-17 19:09:06,898 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [18/120s]: bad status code [404]
[   60.046866] cloud-init[1072]: 2019-05-17 19:09:09,948 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [21/120s]: bad status code [404]
[   63.103655] cloud-init[1072]: 2019-05-17 19:09:13,004 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [24/120s]: bad status code [404]
[   66.156222] cloud-init[1072]: 2019-05-17 19:09:16,057 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [28/120s]: bad status code [404]
[   69.208272] cloud-init[1072]: 2019-05-17 19:09:19,109 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [31/120s]: bad status code [404]
[   73.262001] cloud-init[1072]: 2019-05-17 19:09:23,163 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [35/120s]: bad status code [404]
[   77.490188] cloud-init[1072]: 2019-05-17 19:09:27,391 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [39/120s]: bad status code [404]
[   81.543769] cloud-init[1072]: 2019-05-17 19:09:31,444 - url_helper.py[WARNING]: Calling 'http://169.254.169.254/2009-04-04/meta-data/instance-id' failed [43/120s]: bad status code [404]

Comment 13 Alexander Chuzhoy 2019-05-17 19:10:51 UTC
Note: this also affects boot time of the BM instance - much longer.

Comment 14 Riccardo Pittau 2019-05-20 07:36:08 UTC
Looking at the logs it seems the instance is indeed trying to use the correct metadata server ip, but since the route rule is missing for 169.254.169.254 it can't reach it.
As a consequence, we have first a no route to host to 169.254.169.254, and then the server trying to fall-back to 192.168.24.1 (gateway) to retrieve the metadata.
The route rule to reach the metadata ip should be added by neutron during vm creation, specifically by the neutron dhcp service.
It would be interesting to verify that the metadata service is reachable after manually adding the route rule, to exclude any other possible networking service issues.

Comment 16 Bob Fournier 2019-05-21 19:51:02 UTC
Daniel - per Dmitry's comment in https://review.opendev.org/#/c/502943/32/puppet/services/ovn-controller.yaml, is there any downside to reverting the change setting force_config_drive to false?

Comment 21 Bob Fournier 2019-05-29 20:37:02 UTC
Looks like force_config_drive is now set to true using latest compose (5/29)

[root@undercloud-0 etc]# rpm -qa | grep tripleo-heat
openstack-tripleo-heat-templates-10.5.1-0.20190528190414.f41e7e4.1.el8ost.noarch

[root@undercloud-0 etc]# grep -r force_config_drive *
puppet/hieradata/service_configs.json:    "nova::compute::force_config_drive": true,

Comment 22 Bob Fournier 2019-05-30 16:11:10 UTC
force_config_drive is also true on controller nodes

[heat-admin@controller-0 puppet]$ sudo grep -r force_config_drive *
hieradata/service_configs.json:    "nova::compute::force_config_drive": true,

Comment 23 mlammon 2019-06-04 13:49:48 UTC
Env:

openstack-tripleo-heat-templates-10.5.1-0.20190528190414.f41e7e4.1.el8ost.noarch

(undercloud) [stack@undercloud-0 ~]$ sudo grep -r force_config_drive /etc/puppet/hieradata/service_configs.json
    "nova::compute::force_config_drive": true

Latest test no longer see the issue ssh to instance

Comment 26 errata-xmlrpc 2019-09-21 11:21:45 UTC
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/RHEA-2019:2811


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