Duplex: CirrOS VM login takes too much time, and throw different log errors

[Ricardo Perez]

Brief Description
-----------------
After launching a VM with CirrOS, an with a running VM state. If you try to login into the VM using virsh,
this operation takes ~5 minutes, and it throws a lot of errors in the console.

Severity
--------
<Minor: System/Feature is usable with minor issue>

Steps to Reproduce
------------------
1.- Follow the instructions described here to setup a StarlingX duplex configuration:
https://wiki.openstack.org/wiki/StarlingX/Containers/InstallationOnAIODX

2.- Download a CirrOS image from here:
wget http://download.cirros-cloud.net/0.4.0/cirros-0.4.0-x86_64-disk.img

3.- Create an Image (as root user _not_ as keystone_admin)
openstack image create --container-format bare --disk-format qcow2 --file cirros-0.4.0-x86_64-disk.img cirros

4.- Create a VM
openstack server create --image cirros --flavor m1.tiny --network public-net0 vm1

5.- List the VMs running
sudo virsh list

6.- Login into the previously created VM
sudo virsh consle <ID>

Expected Behavior
------------------
You should be able to see the login prompt from CirrOS after few seconds (5 or less).

Actual Behavior
----------------
Actually it takes ~5 minutes to see the CirrOS login console and several error messages are sent out to the CirrOS login console. Even that using 'openstack server list' you will be able to see an IP address, if you login into the VM you aren't getting the listed IP inside the VM.

Reproducibility
---------------
<Reproducible> All the times

System Configuration
--------------------
<Two node system> Duplex

Branch/Pull Time/Commit
-----------------------
[sysadmin@controller-0 ~(keystone_admin)]$ cat /etc/build.info
###
### StarlingX
### Built from master
###

OS="centos"
SW_VERSION="19.01"
BUILD_TARGET="Host Installer"
BUILD_TYPE="Formal"
BUILD_ID="20190630T233000Z"

JOB="STX_build_master_master"
<email address hidden>"
BUILD_NUMBER="166"
BUILD_HOST="starlingx_mirror"
BUILD_DATE="2019-06-30 23:30:00 +0000"

Last Pass
---------
BUILD_DATE="2019-06-04 01:19:48 +0000"

Timestamp/Logs
--------------

controller-0:~# sudo virsh list
 Id Name State
-----------------------------------
 2 instance-00000004 running

controller-0:~# sudo virsh console 2
Connected to domain instance-00000004
Escape character is ^]

Usage: /sbin/cirros-dhcpc <up|down>
No lease, failing
WARN: /etc/rc3.d/S40-network failed
checking http://169.254.169.254/2009-04-04/instance-id
failed 1/20: up 180.95. request failed
failed 2/20: up 182.98. request failed
failed 3/20: up 184.99. request failed
failed 4/20: up 186.99. request failed
failed 5/20: up 188.99. request failed
failed 6/20: up 191.00. request failed
failed 7/20: up 193.00. request failed
failed 8/20: up 195.01. request failed
failed 9/20: up 197.01. request failed
failed 10/20: up 199.02. request failed
failed 11/20: up 201.02. request failed
failed 12/20: up 203.03. request failed
failed 13/20: up 205.03. request failed
failed 14/20: up 207.04. request failed
failed 15/20: up 209.04. request failed
failed 16/20: up 211.04. request failed
failed 17/20: up 213.05. request failed
failed 18/20: up 215.05. request failed
failed 19/20: up 217.06. request failed
failed 20/20: up 219.06. request failed
failed to read iid from metadata. tried 20
failed to get instance-id of datasource
Top of dropbear init script
Starting dropbear sshd: failed to get instance-id of datasource
OK
GROWROOT: CHANGED: partition=1 start=18432 old: size=71647 end=90079 new: size=2078687,end=2097119
=== system information ===
Platform: OpenStack Foundation OpenStack Nova
Container: none
Arch: x86_64
CPU(s): 1 @ 2593.898 MHz
Cores/Sockets/Threads: 1/1/1
Virt-type:
RAM Size: 488MB
Disks:
NAME MAJ:MIN SIZE LABEL MOUNTPOINT
vda 253:0 1073741824
vda1 253:1 1064287744 cirros-rootfs /
vda15 253:15 8388608
=== sshd host keys ===
-----BEGIN SSH HOST KEY KEYS-----
ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC7qEBGMbJj9eUYYayoxt5Wg+Gk6D2CvIc6MQqK3MKcO/mbKlXo4BqX+gbz/RAX4F/Ll3pa5TSHhUS/MjjQIA++OJHegK0OfwjbUeeYditGNpibP6JBh1Q87/onTiZcbIrfQ4LP5Q7Gy3ygeaLo1A0V0kq1AP6s0nIa5 0aWf2i//Z9mBaTUTjDO1iZ9A4sxstAjW1wHRrX3ZbMCmfsCgOuiUV4MpUxat3wfZVB4QzXFCii2cLr5MHvmlWBEcxSxMvEXiBndnEPV+378mj9Mub5pA3sdKIr9brRh47SEQGBgXvwz63tJfBkszl6YVaWU9Si2SFP8ZhcHWYWyB54HlgHn root@cirros
ssh-dss AAAAB3NzaC1kc3MAAACBAJVk+5EEGGAjq8eub/xMyqOgIpOKkOIbCJeHBAXPNroM/BHhvZepjVizPK/SNfW9i1C2TwXHYMWL4AnZXpes5GwSz+GiVnnLzcgyfT9ZC/+ezsl7HeBcFsugh3hXBzeu2zxTghLh+k5OotmCtx0bEY3o4r5YZXT+ih8s6Ay6a0dzA AAAFQCNvrbWAmPYiBJ9FvaL6qEEmb+zXwAAAIBliWisbuW8U9UjBN9Pby7rXa/m3qui0ShmQFQxuNG+sbsTknbrDYa1b+lHg/Qducne2DDaqLD/r8AGDdnoCxYwlwpgwuN1N94hywXnk31e7UHovpHHTzM3Nw9mFxhXYQkvBZv5wKitqlYBno5e3dBKK0lifkb31FS4l5 7fqq6DEAAAAIBP06PSJ3jfKmlgxXlxQddGbuKX06mhOHGh8Y+QM1vgJTAMp/r0JHJ8uJUPF7T7qitgxC8oRVC6slEMouT9Sz1NpoZ+mFNb83j3py5RPSixheP6roYK7LTyh3B5tcQ9eRq9U2u/jk+7VP66+ROjy1A2/1szl0KkuaNFUOOIzd7WDQ== root@cirros
-----END SSH HOST KEY KEYS-----
=== network info ===
if-info: lo,up,127.0.0.1,8,,
if-info: eth0,up,,8,fe80::f816:3eff:fe18:ba53/64,
ip-route6:fe80::/64 dev eth0 metric 256
ip-route6:unreachable default dev lo metric -1 error -101
ip-route6:ff00::/8 dev eth0 metric 256
ip-route6:unreachable default dev lo metric -1 error -101
=== datasource: None None ===
=== cirros: current=0.4.0 uptime=221.84 ===
=== pinging gateway failed, debugging connection ===
############ debug start ##############
### /etc/init.d/sshd start
Top of dropbear init script
Starting dropbear sshd: failed to get instance-id of datasource
FAIL
### ifconfig -a
eth0 Link encap:Ethernet HWaddr FA:16:3E:18:BA:53
          inet6 addr: fe80::f816:3eff:fe18:ba53/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
          RX packets:0 errors:0 dropped:0 overruns:0 frame:0
          TX packets:10 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:0 (0.0 B) TX bytes:1332 (1.3 KiB)

lo Link encap:Local Loopback
          inet addr:127.0.0.1 Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
          UP LOOPBACK RUNNING MTU:65536 Metric:1
          RX packets:12 errors:0 dropped:0 overruns:0 frame:0
          TX packets:12 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1
          RX bytes:1020 (1020.0 B) TX bytes:1020 (1020.0 B)

### route -n
Kernel IP routing table
Destination Gateway Genmask Flags Metric Ref Use Iface
### cat /etc/resolv.conf
cat: can't open '/etc/resolv.conf': No such file or directory
### gateway not found
/sbin/cirros-status: line 1: can't open /etc/resolv.conf: no such file
### pinging nameservers
### uname -a
Linux cirros 4.4.0-28-generic #47-Ubuntu SMP Fri Jun 24 10:09:13 UTC 2016 x86_64 GNU/Linux
### lsmod
Module Size Used by Not tainted
nls_iso8859_1 16384 0
isofs 40960 0
ip_tables 24576 0
x_tables 36864 1 ip_tables
pcnet32 45056 0
8139cp 28672 0
mii 16384 2 pcnet32,8139cp
ne2k_pci 16384 0
8390 20480 1 ne2k_pci
e1000 135168 0
virtio_scsi 20480 0
### dmesg | tail
[ 1.162710] random: dd urandom read with 5 bits of entropy available
[ 1.258431] usb 1-1: new full-speed USB device number 2 using uhci_hcd
[ 1.419174] usb 1-1: New USB device found, idVendor=0627, idProduct=0001
[ 1.419182] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=5
[ 1.419187] usb 1-1: Product: QEMU USB Tablet
[ 1.419191] usb 1-1: Manufacturer: QEMU
[ 1.419195] usb 1-1: SerialNumber: 42
[ 1.750484] tsc: Refined TSC clocksource calibration: 2593.898 MHz
[ 1.750488] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2563b7b6e37, max_idle_ns: 440795209024 ns
[ 222.089354] EXT4-fs (vda1): resizing filesystem from 32768 to 1039340 blocks
### tail -n 25 /var/log/messages
Jul 4 18:16:36 cirros kern.info kernel: [ 1.769029] tsc: Refined TSC clocksource calibration: 2593.891 MHz
Jul 4 18:16:36 cirros kern.info kernel: [ 1.769033] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2563b0e36c4, max_idle_ns: 440795206265 ns
Jul 5 12:45:42 cirros syslog.info syslogd started: BusyBox v1.23.2
Jul 5 12:45:42 cirros kern.notice kernel: klogd started: BusyBox v1.23.2 (2017-11-20 02:37:12 UTC)
Jul 5 12:45:42 cirros kern.info kernel: [ 0.000000] Initializing cgroup subsys cpuset
Jul 5 12:45:42 cirros kern.info kernel: [ 0.000000] Initializing cgroup subsys cpu
Jul 5 12:45:42 cirros kern.info kernel: [ 0.000000] Initializing cgroup subsys cpuacct
Jul 5 12:45:42 cirros kern.notice kernel: [ 0.000000] Linux version 4.4.0-28-generic (buildd@lcy01-13) (gcc version 5.3.1 20160413 (Ubuntu 5.3.1-14ubuntu2.1) ) #47-Ubuntu SMP Fri Jun 24 10:09:13 UT C 2016 (Ubuntu 4.4.0-28.47-generic 4.4.13)
Jul 5 12:45:42 cirros kern.info kernel: [ 0.000000] Command line: LABEL=cirros-rootfs ro console=tty1 console=ttyS0
Jul 5 12:45:42 cirros kern.info kernel: [ 0.000000] KERNEL supported cpus:
Jul 5 12:45:42 cirros kern.info kernel: [ 0.000000] Intel GenuineIntel
Jul 5 12:45:42 cirros kern.info kernel: [ 0.000000] AMD AuthenticAMD
Jul 5 12:45:42 cirros kern.info kernel: [ 0.000000] Centaur CentaurHauls
Jul 5 12:45:42 cirros kern.info kernel: [ 0.000000] x86/fpu: Legacy x87 FPU detected.
Jul 5 12:45:42 cirros kern.notice kernel: [ 1.162710] random: dd urandom read with 5 bits of entropy available
Jul 5 12:45:42 cirros kern.info kernel: [ 1.258431] usb 1-1: new full-speed USB device number 2 using uhci_hcd
Jul 5 12:45:42 cirros kern.info kernel: [ 1.419174] usb 1-1: New USB device found, idVendor=0627, idProduct=0001
Jul 5 12:45:42 cirros kern.info kernel: [ 1.419182] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=5
Jul 5 12:45:42 cirros kern.info kernel: [ 1.419187] usb 1-1: Product: QEMU USB Tablet
Jul 5 12:45:42 cirros kern.info kernel: [ 1.419191] usb 1-1: Manufacturer: QEMU
Jul 5 12:45:42 cirros kern.info kernel: [ 1.419195] usb 1-1: SerialNumber: 42
Jul 5 12:45:43 cirros kern.info kernel: [ 1.750484] tsc: Refined TSC clocksource calibration: 2593.898 MHz
Jul 5 12:45:43 cirros kern.info kernel: [ 1.750488] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2563b7b6e37, max_idle_ns: 440795209024 ns
Jul 5 12:49:23 cirros authpriv.info dropbear[348]: Running in background
Jul 5 12:49:23 cirros kern.info kernel: [ 222.089354] EXT4-fs (vda1): resizing filesystem from 32768 to 1039340 blocks
############ debug end ##############
/dev/root resized successfully [took 0.21s]
  ____ ____ ____
 / __/ __ ____ ____ / __ \/ __/
/ /__ / // __// __// /_/ /\ \
\___//_//_/ /_/ \____/___/
   http://cirros-cloud.net

login as 'cirros' user. default password: 'gocubsgo'. use 'sudo' for root.
cirros login:cirros
$
$ ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue qlen 1
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast qlen 1000
    link/ether fa:16:3e:18:ba:53 brd ff:ff:ff:ff:ff:ff
    inet6 fe80::f816:3eff:fe18:ba53/64 scope link
       valid_lft forever preferred_lft forever
$
controller-0:~# openstack server list
+--------------------------------------+------+--------+-----------------------------+--------+---------+
| ID | Name | Status | Networks | Image | Flavor |
+--------------------------------------+------+--------+-----------------------------+--------+---------+
| cc1e49f6-b096-41db-964d-58b86eadcc3e | vm1 | ACTIVE | public-net0=192.168.101.218 | cirros | m1.tiny |
+--------------------------------------+------+--------+-----------------------------+--------+---------+
controller-0:~# ping 192.168.101.218
PING 192.168.101.218 (192.168.101.218) 56(84) bytes of data.
From 192.168.200.1 icmp_seq=1 Destination Net Unreachable
From 192.168.200.1 icmp_seq=2 Destination Net Unreachable
^C
--- 192.168.101.218 ping statistics ---
2 packets transmitted, 0 received, +2 errors, 100% packet loss, time 999ms

Test Activity
-------------
[Regression Testing]

[Ghada Khalil (gkhalil)]

Do you see the same issue when using other cloud images - like ubuntu? Is it possible this is a guest image issue?

[Ricardo Perez (richomx)]

Hi Ghada, this issue is no longer present in this build image version:

controller-0:~# cat /etc/build.info
###
### StarlingX
### Built from master
###

OS="centos"
SW_VERSION="19.01"
BUILD_TARGET="Host Installer"
BUILD_TYPE="Formal"
BUILD_ID="20190707T233000Z"

JOB="STX_build_master_master"
<email address hidden>"
BUILD_NUMBER="173"
BUILD_HOST="starlingx_mirror"
BUILD_DATE="2019-07-07 23:30:00 +0000"

[Ghada Khalil (gkhalil)]

Closing based on Ricardo's input above that this was a one-time occurrence that is not reproducible.

[Juan Pablo Gomez (jpgomez)]

Opening this BUG, also is presented in Standard Storage configuration
After get into the Virsh Console, console got freeze

[Juan Pablo Gomez (jpgomez)]

Logs Attached

[Juan Pablo Gomez (jpgomez)]

Virsh console list is not working with Cirros and with CentOS image also, the error for both images is:

error: failed to connect to the hypervisor
error: Failed to connect socket to '/var/run/libvirt/libvirt-sock': No such file or directory

[Ghada Khalil (gkhalil)]

This could be an issue with dhcp configuration or a neutron issue given the original occurrence reports the VM failing to get an IP address. Assigning to the networking team to investigate.

[Ghada Khalil (gkhalil)]

Marking as stx.2.0 / medium priority until further investigation. Based on the bug info, it may be an intermittent issue?

[Gopinath (gprabakx)]

Hi, Similar issue is observed in MN-External, when an instance is created in compute and when i reboot the compute in which the instance exist.

[Gopinath (gprabakx)]

Hi, I have created two instance in External to ping between instance with Below steps and when i login to console it hung.

1.openstack flavor create --ram 2048 --vcpus 1 --disk 1 --property hw:mem_page_size=large vm_flavor
2.openstack image create --file cirros-0.4.0-x86_64-disk.img --disk-format qcow2 vm_image
3.openstack network create vm_network
4.openstack subnet create --network vm_network --subnet-range 192.168.0.0/24 --ip-version 4 --dhcp vm_subnet
5.openstack server create --nic net-id=75025019-1a3d-4c3f-aed2-a65a36bcf2d9 --flavor vm_flavor --image vm_image vm
6.openstack server create --nic net-id=75025019-1a3d-4c3f-aed2-a65a36bcf2d9 --flavor vm_flavor --image vm_image vm_2
7.Find the host and from host sudo virsh console

Snippet:
compute-0:~$ sudo virsh list
Password:
 Id Name State
-----------------------------------
 1 instance-00000009 running
 2 instance-00000006 running

compute-0:~$ sudo virsh console 1
Connected to domain instance-00000009
Escape character is ^]

It hung and could not perform any command in instance.

[Gongjun Song (songgongjun)]

Hello,

 I have a question, do you use Open vSwitch or Open vSwitch with DPDK when building a duplex environment?

thanks,
Gongjun

At 2019-08-01 06:38:06, "Gopinath" <email address hidden> wrote:
>Hi, Similar issue is observed in MN-External, when an instance is
>created in compute and when i reboot the compute in which the instance
>exist.
>
>--
>You received this bug notification because you are a bug assignee.
>https://bugs.launchpad.net/bugs/1835575
>
>Title:
> Duplex: CirrOS VM login takes too much time, and throw different log
> errors
>
>Status in StarlingX:
> Triaged
>
>Bug description:
> Brief Description
> -----------------
> After launching a VM with CirrOS, an with a running VM state. If you try to login into the VM using virsh,
> this operation takes ~5 minutes, and it throws a lot of errors in the console.
>
> Severity
> --------
> <Minor: System/Feature is usable with minor issue>
>
> Steps to Reproduce
> ------------------
> 1.- Follow the instructions described here to setup a StarlingX duplex configuration:
> https://wiki.openstack.org/wiki/StarlingX/Containers/InstallationOnAIODX
>
> 2.- Download a CirrOS image from here:
> wget http://download.cirros-cloud.net/0.4.0/cirros-0.4.0-x86_64-disk.img
>
> 3.- Create an Image (as root user _not_ as keystone_admin)
> openstack image create --container-format bare --disk-format qcow2 --file cirros-0.4.0-x86_64-disk.img cirros
>
> 4.- Create a VM
> openstack server create --image cirros --flavor m1.tiny --network public-net0 vm1
>
> 5.- List the VMs running
> sudo virsh list
>
> 6.- Login into the previously created VM
> sudo virsh consle <ID>
>
>
> Expected Behavior
> ------------------
> You should be able to see the login prompt from CirrOS after few seconds (5 or less).
>
> Actual Behavior
> ----------------
> Actually it takes ~5 minutes to see the CirrOS login console and several error messages are sent out to the CirrOS login console. Even that using 'openstack server list' you will be able to see an IP address, if you login into the VM you aren't getting the listed IP inside the VM.
>
> Reproducibility
> ---------------
> <Reproducible> All the times
>
> System Configuration
> --------------------
> <Two node system> Duplex
>
> Branch/Pull Time/Commit
> -----------------------
> [sysadmin@controller-0 ~(keystone_admin)]$ cat /etc/build.info
> ###
> ### StarlingX
> ### Built from master
> ###
>
> OS="centos"
> SW_VERSION="19.01"
> BUILD_TARGET="Host Installer"
> BUILD_TYPE="Formal"
> BUILD_ID="20190630T233000Z"
>
> JOB="STX_build_master_master"
> <email address hidden>"
> BUILD_NUMBER="166"
> BUILD_HOST="starlingx_mirror"
> BUILD_DATE="2019-06-30 23:30:00 +0000"
>
>
> Last Pass
> ---------
> BUILD_DATE="2019-06-04 01:19:48 +0000"
>
> Timestamp/Logs
> --------------
>
> controller-0:~# sudo virsh list
> Id Name State
> -----------------------------------
> 2 instance-00000004 running
>
> controller-0:~# sudo virsh console 2
> Connected to domain instance-00000004
> Escape character is ^]
>
>
> Usage: /sbin/cirros-dhcpc <up|down>
> No lease, failing
> W...

[Gongjun Song (songgongjun)]

Hi all,

The original bug reported by Ricardo and the bug reported by Juan and Gopinath are different bugs. Need Juan and Gopinath to report a new bug. The second bug is related to nova. Need nova expert to analyse the second bug.

The original bug reported by Ricardo is related to networking. It takes about 5 minutes to log in the VM but you can still log in the VM. It means the VM is created successfully but VM can't get an IP from DHCP.
As confirmed by Ricardo, this bug is no longer present. And I can't reproduce this bug either on duplex system using 0715 iso image and OVS. The log is as following：
    controller-0:~# sudo virsh console 2
       Connected to domain instance-00000004
       Escape character is ^]
       Usage: /sbin/cirros-dhcpc <up|down>
       No lease, failing
       WARN: /etc/rc3.d/S40-network failed
       checking http://169.254.169.254/2009-04-04/instance-id
       failed 1/20: up 180.95. request failed
       failed 2/20: up 182.98. request failed
       failed 3/20: up 184.99. request failed
       failed 4/20: up 186.99. request failed

For the bug reported by Juan Pablo Gomez and Gopinath, the virsh console gets frozen after the following command is executed because the VM was not created successfully:
   sudo virsh console 1
The log is as following：
    compute-0:~$ sudo virsh console 1
       Connected to domain instance-00000009
       Escape character is ^]

[Gongjun Song (songgongjun)]

Hi Juan，

You report a bug that the virsh console gets frozen after the following command
   sudo virsh console <ID>

Which case did you have the same result?
case1：
   controller-0:~# sudo virsh console 2
       Connected to domain instance-00000004
       Escape character is ^]
       Usage: /sbin/cirros-dhcpc <up|down>
       No lease, failing
       WARN: /etc/rc3.d/S40-network failed
       checking http://169.254.169.254/2009-04-04/instance-id
       failed 1/20: up 180.95. request failed
       failed 2/20: up 182.98. request failed
       failed 3/20: up 184.99. request failed
       failed 4/20: up 186.99. request failed

case2:
    compute-0:~$ sudo virsh console 1
       Connected to domain instance-00000009
       Escape character is ^]

[yong hu (yhu6)]

I would close this LP as @songgongjun analyzed and @ricardo confirmed (not reproduced).
And as follow-up @JP might create another LP to track the issue with different symptom.