Finding serial console log of a nova instance

The other day I was debugging why a volume booted nova instance doesn’t get dhcp leases. For that I need to find networking information of the instance during boot. Fortunately, nova attempts to log the boot details to a serial console log. To find where it’s located..

First, let’s list the instances which we care about:

$ nova list | grep f17
| 220d6e57-f7ad-4256-a861-7855ffc6788f | f17-builder       | ACTIVE  | novanetwork=192.168.32.4 |
| f1169841-5e67-45d9-85c4-0d44bd3bec90 | f17_volume_backed | ACTIVE | novanetwork=192.168.32.6 |

Then, grep that instance UUID in /etc/libvirt/qemu/* to find what’s the libvirt id of a specific nova instance:

$ grep f1169841-5e67-45d9-85c4-0d44bd3bec90 \
  /etc/libvirt/qemu/* 
/etc/libvirt/qemu/instance-00000007.xml:  f1169841-5e67-45d9-85c4-0d44bd3bec90
/etc/libvirt/qemu/instance-00000007.xml:      f1169841-5e67-45d9-85c4-0d44bd3bec90

$ virsh list | grep instance-00000007
 10    instance-00000007              running

From above, the libvirt instance is called instance-00000007

To find path to the serial console log of the instance, grep its libvirt xml information for the relevant fragment:

$ virsh dumpxml  instance-00000007 | grep -i console
      <source path='/var/lib/nova/instances/instance-00000007/console.log'/>
    <console type='file'>
      <source path='/var/lib/nova/instances/instance-00000007/console.log'/>
    </console>

The console log of the cirros image runs a bunch of useful debug commands after booting an instance — which gave me an insight that it wasn’t getting dhcp leases. Listing the commands it ran from the console.log for reference:

$ /etc/rc.d/init.d/sshd start
$ ifconfig -a
$ route -n
$ cat /etc/resolv.conf
# pinging nameservers
$ uname -a
$ dmesg | tail
$ tail -n 25 /var/log/messages

Also, for reference, relevant xml snippet of the console information:

$ virsh dumpxml instance-00000003 | \
  egrep -i 'serial type' -A9
    <serial type='file'>
      <source path='/var/lib/nova/instances/instance-00000003/console.log'/>
      <target port='0'/>
      <alias name='serial0'/>
    </serial>
    <serial type='pty'>
      <source path='/dev/pts/1'/>
      <target port='1'/>
      <alias name='serial1'/>
    </serial>
    <console type='file'>
      <source path='/var/lib/nova/instances/instance-00000003/console.log'/>
      <target type='serial' port='0'/>
      <alias name='serial0'/>
    </console>

Advertisement

Debugging nova — a small illustration with pdb

The other day, I was testing non-ascii characters with nova commands. I started with adding an ssh key to nova with a non-ascii name, not realizing key-pair names won’t support them. This is how we ended up figuring it after a small debugging session with Flavio.

First, let’s try to add an ssh keypair & attempt to provide a non-ascii name:

$ nova keypair-add --pub_key ~/.ssh/id_rsa.pub äçë
ERROR: Keypair data is invalid (HTTP 400) (Request-ID: req-5a1a2683-d658-417b-a805-91346d5202dc)

Note – supplying --debug provides more info on the stdout. However, we’re interested to find out the root cause.

Let’s find out why the key-pair data is invalid by stepping through code using pdb. To start, stop the nova-api service, and ensure none of its processes are running :

$ service openstack-nova-api stop
$ ps aux | grep -i nova-api

Ensure to have the config attribute osapi_compute_workers set to 1 — I had it set to 5 while testing rhbz-81349 — so they won’t run in parallel, in /etc/nova/nova.conf :

$ grep osapi_compute_workers \
  /etc/nova/nova.conf | grep -v ^$ | grep -v ^# \
  osapi_compute_workers=1

Let’s set the pdb trace — import pdb; pdb.set_trace() — in the source code to break into the debugger — /usr/lib/python2.6/site-packages/nova/compute/api.py

Code context — I’m setting the breakpoint just after the self-explanatory function _validate_keypair_name :

.
.
class KeypairAPI(base.Base):
    """Sub-set of the Compute Manager API for managing key pairs."""
    def __init__(self, **kwargs):
        super(KeypairAPI, self).__init__(**kwargs)

    def _validate_keypair_name(self, context, user_id, key_name):

        import pdb; pdb.set_trace()       

        safechars = "_- " + string.digits + string.ascii_letters
        clean_value = "".join(x for x in key_name if x in safechars)
.
.

Now, invoke the nova-api service manually:

$ /usr/bin/nova-api --config-file \
  /usr/share/nova/nova-dist.conf --config-file \
  /etc/nova/nova.conf --logfile /var/log/nova/api.log

From a different terminal, again, try to create a keypair with non-ascii characters — this time, it’ll let us break into the debugger

$ nova keypair-add --pub-key ~/.ssh/id_rsa.pub äçë

Now, from shell from where we invoked the nova-api server daemon, a debugger Pdb would be waiting, to step through the code, do:

• type n — which continues execution until the next line in the current function is reached
• print the value safechars — indicates what values are considered safe — which is what we’re trying to find out
• quit the debugger

.
.
.
2013-03-26 19:56:26 71243 DEBUG nova.utils [-] Reloading cached file /etc/nova/policy.json read_cached_file /usr/lib/python2.6/site-packages/nova/uti1
2013-03-26 19:56:27 INFO nova.api.openstack.wsgi [req-9ef1fd31-0cec-4465-894a-f1ae0fa9a77e 320ce46de7e24a75a7ff8906d7355ff7 57ff99aae24b4035b52177a72s
> /usr/lib/python2.6/site-packages/nova/compute/api.py(2198)_validate_keypair_name()
-> safechars = "_- " + string.digits + string.ascii_letters
(Pdb) 
(Pdb)  n
> /usr/lib/python2.6/site-packages/nova/compute/api.py(2199)_validate_keypair_name()
-> clean_value = "".join(x for x in key_name if x in safechars)
(Pdb)  safechars
 '_- 0123456789abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ' 
(Pdb) 
(Pdb)  quit

So, the above indicates non-ascii characters are not allowed for key-pair names.

Clean up

Remove the debugging fragment from the source file. Start the nova-api server daemon gracefully —

 $ service openstack-nova-api start 

OpenStack nova — dealing with unused base images

Nova uses disk image cache management to handle unused base disk images, validate their integrity, etc. In this entry, let’s try to find out how unused base images are cleaned up. For context on Openstack’s libvirt base images, take a look at Pádraig’s excellent write-up on life of an OpenStack libvirt image. And a prior related post on disk image usage by nova.

Set the relevant config directives
Let’s set periodic_interval=1 — the no. of seconds between running periodic tasks; image_cache_manager_interval=1 — the no. of periodic scheduler ticks to wait between runs of the image cache manager. I’ve set both of them to ‘1’ for test purpose, and grepped to ensure the change reflects

$ sudo echo -e "periodic_interval=1\nimage_cache_manager_interval=1" >> /etc/nova/nova.conf
$ sudo egrep '^image_cache_manager_interval|^periodic_interval' /etc/nova/nova.conf 
periodic_interval=1
image_cache_manager_interval=1
$

Restart all openstack nova services, so the config changes take effect:

$ for j in `for i in $(ls -1 /etc/init.d/openstack-nova-*) ;\
  do $i status | grep running ;\
  done | awk '{print $1}'` ; do service $j restart ; done

Delete a running nova instance, verify logs to see the effect of config changes

Let’s stop and delete the only nova instance running — so that nova’s image cache manager knows the image is no longer in use, and the previously enabled config options can take effect.

$ nova list
+--------------------------------------+---------+--------+-------------------+
| ID                                   | Name    | Status | Networks          |
+--------------------------------------+---------+--------+-------------------+
| 11c1997a-b1ff-46ef-b96c-f329576de8d6 | fedora4 | ACTIVE | net1=10.xx.yyy.zz |
+--------------------------------------+---------+--------+-------------------+
$ nova stop 11c1997a-b1ff-46ef-b96c-f329576de8d6
$ nova delete 11c1997a-b1ff-46ef-b96c-f329576de8d6
$ nova list
$ sudo virsh list --all
 Id    Name                           State
----------------------------------------------------

List out the base_images (now they should become invalid) :

$ sudo ls -lash /var/lib/nova/instances/_base/
total 1.7G
4.0K drwxr-xr-x. 2 nova nova 4.0K Feb 18 00:41 .
4.0K drwxr-xr-x. 3 nova nova 4.0K Feb 18 04:01 ..
739M -rw-r--r--. 1 nova nova 9.8G Feb 18 04:01 06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3
741M -rw-r--r--. 1 nova nova  20G Feb 18 04:01 06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20
241M -rw-r--r--. 1 nova nova 241M Feb 18 00:41 06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3.part
$ 

At this point, the — now invalid — base_images should’ve been deleted. Let’s look at nova’s compute logs, location: /var/log/nova/compute.log

.
.
2012-02-18 04:13:03 37747 INFO nova.compute.resource_tracker [-] Compute_service record updated for interceptor.foo.bar.com 
2012-02-18 04:13:03 37747 WARNING nova.virt.libvirt.imagecache [-] Unknown base file: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3
2012-02-18 04:13:03 37747 WARNING nova.virt.libvirt.imagecache [-] Unknown base file: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20
2012-02-18 04:13:03 37747 INFO nova.virt.libvirt.imagecache [-] Removable base files: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3 /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20

Now, it says, base-files are too young to remove:

.
.
012-01-18 04:16:46 37747 INFO nova.virt.libvirt.imagecache [-] Base file too young to remove: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3
2012-02-18 04:16:46 37747 INFO nova.virt.libvirt.imagecache [-] Base file too young to remove: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20

Let’s drill down a bit further, by searching in upstream nova code for how young is ‘too young’:

$ git clone git://github.com/openstack/nova.git && cd nova
$ grep FLAGS.remove_unused_original_minimum_age_seconds nova/virt/libvirt/imagecache.py
            maxage = FLAGS.remove_unused_original_minimum_age_seconds
$ git grep remove_unused_original_minimum_age_seconds
etc/nova/nova.conf.sample:# remove_unused_original_minimum_age_seconds=86400
nova/virt/libvirt/imagecache.py:    cfg.IntOpt('remove_unused_original_minimum_age_seconds',
nova/virt/libvirt/imagecache.py:            maxage = FLAGS.remove_unused_original_minimum_age_seconds
$

Ok, 86400 seconds (24 hours) appears to be the default time. Let’s, set that value to 60 seconds in nova.conf and restart all nova services again:

$ sudo echo -e "remove_unused_original_minimum_age_seconds=60" >> /etc/nova/nova.conf
$ sudo egrep '^image_cache_manager_interval|^periodic_interval|^remove_unused_original_minimum_age_seconds' /etc/nova/nova.conf 
periodic_interval=1
image_cache_manager_interval=1
remove_unused_original_minimum_age_seconds=60
$ 

Restart all nova services again:

$ sudo -i
$ for j in `for i in $(ls -1 /etc/init.d/openstack-nova-*) ;\
  do $i status | grep running ;\
  done | awk '{print $1}'` ;\
  do service $j restart ; done

Now, the /var/log/compute/compute.log indicates one of the base-files being removed, that’s good:

.
.
2012-02-18 04:24:17 41389 WARNING nova.virt.libvirt.imagecache [-] Unknown base file: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810
a0d1d5d3_20
2012-02-18 04:24:17 41389 INFO nova.virt.libvirt.imagecache [-] Removable base files: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810
a0d1d5d3 /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20
2012-02-18 04:24:17 41389 INFO nova.virt.libvirt.imagecache [-] Removing base file: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3

Let’s check in the nova base images directory. Now, it seems like, two more base_images are still remaining:

$ sudo ls -1 /var/lib/nova/instances/_base/
06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20
06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3.part
$ 

Let’s get back to nova compute.log, it still says ‘Unknown base file’ and ‘Base file too young to remove’:

.
.
2012-02-18 04:50:45 41389 WARNING nova.virt.libvirt.imagecache [-] Unknown base file: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20
2012-02-18 04:50:45 41389 INFO nova.virt.libvirt.imagecache [-] Removable base files: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20
2012-02-18 04:50:45 41389 INFO nova.virt.libvirt.imagecache [-] Base file too young to remove: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20

Let’s check the nova compute.log again — now it’s indicating one of the other two unused base images being deleted — from time-stamps, in 10 minutes.

.
.
2012-02-18 05:01:24 41389 INFO nova.compute.resource_tracker [-] Compute_service record updated for interceptor.foo.bar.com 
2012-02-18 05:01:24 41389 WARNING nova.virt.libvirt.imagecache [-] Unknown base file: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20
2012-02-18 05:01:24 41389 INFO nova.virt.libvirt.imagecache [-] Removable base files: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20
2012-02-18 05:01:24 41389 INFO nova.virt.libvirt.imagecache [-] Removing base file: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20

Now, the only remaining one appears to be a .part image.

$ sudo ls -1 /var/lib/nova/instances/_base/
06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3.part
$

From further investigation by Padraig , the stale .part files turned out to be a different bug (for which he posted a fix upstream) — When converting non-raw (in this case, qcow2) to raw, libvirt leaves behind the original non-raw image on disk.

Finally
Let’s turn the config directives back to sane defaults, and comment out the config directives periodic_interval, image_cache_manager_interval. And, restart all nova services to take the config change effect.

$ sudo sed -i 's/remove_unused_original_minimum_age_seconds=60/remove_unused_originalminimum_age_seconds=86400/' foobar1.txt
$ sudo sed -i 's/periodic_interval=1/\#periodic_interval=1/;s/image_cache_manager_interval=1/\#image_cache_manager_interval=1/' >> /etc/nova/nova.conf
$ for j in `for i in $(ls -1 /etc/init.d/openstack-nova-*) ;\
   do $i status | grep running ;\
  done | awk '{print $1}'` ; do service $j restart ; done

UPDATE: I also had to set the config directive remove_unused_resized_minimum_age_seconds=60 in nova.conf, to remove the re-sized — according to the flavor chosen, in this case, it’s m1.small — raw images from the _base directory.

Nova’s way of using a disk image when it boots a guest for first time

Let’s see how Nova — the compute component of OpenStack — uses a disk image from the time it was initially imported into Glance (OpenStack’s repository for virtual machine disk images) till a new virtual machine instance is booted and running.

I started by downloading a Fedora-17 disk image from here
(Keep a note of the size of the image — 241 MB)

[tuser1@interceptor ~(keystone_user1)]$ ls -lash f17-x86_64-openstack-sda.qcow2 
241M -rw-rw-r--. 1 tuser1 tuser1 241M Jan 13  2012 f17-x86_64-openstack-sda.qcow2
[tuser1@interceptor ~(keystone_user1)]$ 

Import the above Fedora 17 disk image into Glance:

$ . ~/keystone_admin
$ glance image-create --name="fedora-17" --is-public=true \
--disk-format=qcow2 --container-format bare < f17-x86_64-openstack-sda.qcow2

(Note that I have to source Keystone admin credentials to list images from Glance).

Let’s list the current images in Glance:

$ . ~/keystone_tuser1
$ glance image-list
+--------------------------------------+-----------+-------------+------------------+------------+--------+
| ID                                   | Name      | Disk Format | Container
Format | Size       | Status |
+--------------------------------------+-----------+-------------+------------------+------------+--------+
| 1e6292f9-82bd-4cdb-969e-c863cb1c6692 | fedora-17 | qcow2       | bare
| 251985920  | active |
| acc4c853-9153-4e80-b3c8-e253451ae983 | rhel63    | qcow2       | bare
| 1074135040 | active |
+--------------------------------------+-----------+-------------+------------------+------------+--------+
$

List current running Nova instances :

$ nova list
+--------------------------------------+-----------+--------+-------------------+
| ID                                   | Name      | Status | Networks          |
+--------------------------------------+-----------+--------+-------------------+
| 08d616a9-87a1-4c0d-b986-7d6aa5ed6780 | fedora-t1 | ACTIVE | net1=ww.xx.yyy.zz |
| 3e487977-37e8-4f26-9443-d65ecbdf83c9 | fedora-t2 | ACTIVE | net1=ww.xx.yyy.zz |
| 48d9e518-a91f-48db-9d9b-965b243e7113 | fedora-t4 | ACTIVE | net1=ww.xx.yyy.zz |
+--------------------------------------+-----------+--------+-------------------+
$ 

Let’s also list the guests running using libvirt’s virsh :

$ sudo virsh list
 Id    Name                           State
----------------------------------------------------
 12    instance-0000000c              running
 13    instance-0000000d              running
 22    instance-00000012              running

$ 

Find the block device in use for one of the running instances to examine it further — instance-0000000c, in this case:

$ sudo virsh domblklist instance-0000000c
Target     Source
------------------------------------------------
vda        /var/lib/nova/instances/instance-0000000c/disk

$ 

Let’s get information about the disk in use by the above nova instance; specifically, find its backing file:

$ qemu-img info /var/lib/nova/instances/instance-0000000c/disk
image: /var/lib/nova/instances/instance-0000000c/disk
file format: qcow2
virtual size: 20G (21474836480 bytes)
disk size: 149M
cluster_size: 65536
backing file: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20

Now, get information about the “backing file” used by the overlay (used by the running Nova instance above):

$ qemu-img info /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20
image: /var/lib/nova/instances/_base/06a057b9c7b0b27e3b496f53d1e88810a0d1d5d3_20
file format: raw
virtual size: 20G (21474836480 bytes)
disk size: 740M
$ 

It’s worth noting here that the original disk image initially uploaded into glance was a qcow2 image. However, the base image being used by Nova is a raw disk image.

From this, we can see: When booting a virtual machine instance for the first time, Nova does a few things:

1. Make a copy of the original qcow2 disk image from Glance, convert it into a ‘raw’ sparse image & make it a base image (its location – /var/lib/nova/instances/_base) — Reason for turning non-raw to raw, refer “Background info” section below.
2. Expands the size of the base image to 20GB (because, I used the m1.small flavour from Nova, when initially booting the image.)
3. Use this base image & instantiate a copy on write overlay (qcow2) to boot the nova instance.

To demonstrate this post, I used Red Hat OpenStack Folsom, RHEL 6.4, single node, running these services — nova, glance, keystone, cinder; using KVM as the underlying hypervisor.

Background info:

[1] From nova’s git log, the conversion from non ‘raw’ images to ‘raw’ is tracked down to this commit

commit ff9d353b2f4fee469e530fbc8dc231a41f6fed84
Author: Scott Moser 
Date:   Mon Sep 19 16:57:44 2011 -0400

    convert images that are not 'raw' to 'raw' during caching to node
    
    This uses 'qemu-img' to convert images that are not 'raw' to be 'raw'.
    By doing so, it
     a.) refuses to run uploaded images that have a backing image reference
         (LP: #853330, CVE-2011-3147)
     b.) ensures that when FLAGS.use_cow_images is False, and the libvirt
         xml written specifies 'driver_type="raw"' that the disk referenced
         is also raw format. (LP: #837102)
     c.) removes compression that might be present to avoid cpu bottlenecks
         (LP: #837100)
    
    It does have the negative side affect of using more space in the case where
    the user uploaded a qcow2 (or other advanced image format) that could have
    been used directly by the hypervisor.  That could, later, be remedied by
    another 'qemu-img convert' being done to the "preferred" format of the
    hypervisor.

[2] Pádraig Brady pointed out (thank you !) this bz — https://bugs.launchpad.net/nova/+bug/932180 to note further reasons for converting images from non raw to raw.

As an aside, more informaion on disk image size allocation/ performance improvements upstream – https://blueprints.launchpad.net/nova/+spec/preallocated-images

UPDATE : Pádraig Brady writes in excellent detail about the life of an openstack libvirt image — describing Openstack — http://www.pixelbeat.org/docs/openstack_libvirt_images/