Openstack's VM not starting: seems an apparmor + kvm 0.14.0+noroms-0ubuntu4.4 problem

Asked by Giuseppe Civitella on 2011-08-22

Hi,

I'm experiencing a problem about starting virtual machines deployed by openstack on a nova-compute node running on a Natty 11.04 (Linux beta 2.6.38-8-server #42-Ubuntu SMP Mon Apr 11 03:49:04 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux).

Here's a list of nova packages installed on the server (i'm using a milestone version here):

ii nova-common 2011.3~d3-0ubuntu0~ppa1~natty1 OpenStack Compute - common files
ii nova-compute 2011.3~d3-0ubuntu0~ppa1~natty1 OpenStack Compute - compute node
ii nova-doc 2011.3~d3-0ubuntu0~ppa1~natty1 OpenStack Compute - documetation
ii nova-instancemonitor 2011.3~d3-0ubuntu0~ppa1~natty1 monitors the resources usage of your virtual machines
ii python-nova 2011.3~d3-0ubuntu0~ppa1~natty1 OpenStack Compute Python libraries
ii python-novaclient 2.4.2~bzr25-0ubuntu0ppa1~natty3 client library for OpenStack Compute API

The kvm version I'm using here is:

ii kvm 1:84+dfsg-0ubuntu16+0.14.0+noroms+0ubuntu4.4 dummy transitional package from kvm to qemu-kvm
ii qemu-kvm 0.14.0+noroms-0ubuntu4.4 Full virtualization on i386 and amd64 hardware

The problem seems similar the the one described here:
http://www.ubuntu.com/usn/usn-1165-1/

In fact, the vm gets deployed on the nova-compute node but does not start.
In the syslog i can see:

Aug 22 12:16:09 beta kernel: [5174076.278148] type=1400 audit(1314008169.247:109): apparmor="DENIED" operation="open" parent=29235 profile="/usr/lib/libvirt/virt-aa-helper" name="/var/lib/nova/instances/_base/77de68daecd823babbb58edb1c8e14d7106e83bb" pid=20230 comm="virt-aa-helper" requested_mask="r" denied_mask="r" fsuid=0 ouid=108
Aug 22 12:16:09 beta kernel: [5174076.632313] type=1400 audit(1314008169.607:110): apparmor="STATUS" operation="profile_load" name="libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea" pid=20231 comm="apparmor_parser"
Aug 22 12:16:10 beta multipathd: no /block/ in '/devices/virtual/net/vnet0'
Aug 22 12:16:10 beta multipathd: no /block/ in '/devices/virtual/net/vnet0/queues/tx-0'
Aug 22 12:16:10 beta kernel: [5174077.175247] device vnet0 entered promiscuous mode
Aug 22 12:16:10 beta kernel: [5174077.177043] br12: port 2(vnet0) entering forwarding state
Aug 22 12:16:10 beta kernel: [5174077.177046] br12: port 2(vnet0) entering forwarding state
Aug 22 12:16:11 beta libvirtd: 12:16:11.094: 29235: error : qemuMonitorCommandWithHandler:255 : cannot send monitor command 'info chardev': Connection reset by peer
Aug 22 12:16:11 beta libvirtd: 12:16:11.094: 29235: error : qemuMonitorTextGetPtyPaths:2001 : operation failed: failed to retrieve chardev info in qemu with 'info chardev'
Aug 22 12:16:11 beta kernel: [5174078.434976] br12: port 2(vnet0) entering forwarding state
Aug 22 12:16:11 beta multipathd: no /block/ in '/devices/virtual/net/vnet0/queues/tx-0'
Aug 22 12:16:11 beta kernel: [5174078.510639] device vnet0 left promiscuous mode
Aug 22 12:16:11 beta kernel: [5174078.510644] br12: port 2(vnet0) entering disabled state
Aug 22 12:16:11 beta kernel: [5174078.702713] type=1400 audit(1314008171.677:111): apparmor="STATUS" operation="profile_remove" name="libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea" pid=20438 comm="apparmor_parser"

In the dir /etc/apparmor.d/libvirt i can see two files generated by libvirt on vm's deploy:

root@beta:/etc/apparmor.d/libvirt# ls libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea*
libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea.files
root@beta:/etc/apparmor.d/libvirt# cat libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea
#
# This profile is for the domain whose UUID matches this file.
#

#include <tunables/global>

profile libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea {
  #include <abstractions/libvirt-qemu>
  #include <libvirt/libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea.files>

}
root@beta:/etc/apparmor.d/libvirt# cat libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea.files
# DO NOT EDIT THIS FILE DIRECTLY. IT IS MANAGED BY LIBVIRT.
  "/var/log/libvirt/**/instance-00000003.log" w,
  "/var/lib/libvirt/**/instance-00000003.monitor" rw,
  "/var/run/libvirt/**/instance-00000003.pid" rwk,
  "/var/lib/nova/instances/instance-00000003/disk" rw,
  "/var/lib/nova/instances/_base/77de68daecd823babbb58edb1c8e14d7106e83bb" r,
  # don't audit writes to readonly files
  deny "/var/lib/nova/instances/_base/77de68daecd823babbb58edb1c8e14d7106e83bb" w,
  "/var/lib/nova/instances/instance-00000003/console.log" rw,
  "/var/lib/nova/instances/instance-00000003/kernel" r,
  # don't audit writes to readonly files
  deny "/var/lib/nova/instances/instance-00000003/kernel" w,
  "/var/lib/nova/instances/instance-00000003/ramdisk" r,
  # don't audit writes to readonly files
  deny "/var/lib/nova/instances/instance-00000003/ramdisk" w,

I've got another nova-compute node (Linux eta 2.6.38-8-server #42-Ubuntu SMP Mon Apr 11 03:49:04 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux) running the following software on natty:

ii nova-common 2011.2-0ubuntu1 OpenStack Compute - Nova - common files
ii nova-compute 2011.2-0ubuntu1 OpenStack Compute - Nova - compute node

ii kvm 1:84+dfsg-0ubuntu16+0.14.0+noroms+0ubuntu4.3 dummy transitional package from kvm to qemu-kvm
ii qemu-kvm 0.14.0+noroms-0ubuntu4.3 Full virtualization on i386 and amd64 hardware
ii qemu-kvm-extras 0.14.50-2011.03-1-0ubuntu2 QEMU system and user mode emulation (transitional package)
ii qemu-kvm-extras-static 0.14.50-2011.03-1-0ubuntu2 QEMU static user mode emulation binaries (transitional package)

the apparmor profiles that libvirt generates seem quite similar to the other node's ones but i'm definitively able to start vms on this node.

Am I missing something or this is a returning problem?

Thanks
Giuseppe

Question information

Language:
English Edit question
Status:
Solved
For:
Ubuntu qemu-kvm Edit question
Assignee:
No assignee Edit question
Solved by:
Giuseppe Civitella
Solved:
2011-08-22
Last query:
2011-08-22
Last reply:

I've been trying excluding apparmor from the list of suspected.
If i run libvirt in complain mode nothing chenges:
aa-complain /usr/sbin/libvirtd
aa-complain /usr/lib/libvirt/virt-aa-helper
root@beta:/var/lib/nova/instances/instance-00000003# aa-status
apparmor module is loaded.
8 profiles are loaded.
6 profiles are in enforce mode.
   /sbin/dhclient
   /usr/lib/NetworkManager/nm-dhcp-client.action
   /usr/lib/connman/scripts/dhclient-script
   /usr/sbin/mysqld
   /usr/sbin/ntpd
   /usr/sbin/tcpdump
2 profiles are in complain mode.
   /usr/lib/libvirt/virt-aa-helper
   /usr/sbin/libvirtd
2 processes have profiles defined.
1 processes are in enforce mode :
   /usr/sbin/mysqld (1652)
1 processes are in complain mode.
   /usr/sbin/libvirtd (29232)
0 processes are unconfined but have a profile defined.

But if I try to restart the vm by eucatools in the syslog I see:
Aug 22 14:07:38 beta libvirtd: 14:07:38.093: 29237: error : qemudDomainDestroy:3853 : Requested operation is not valid: domain is not running
Aug 22 14:07:39 beta kernel: [5180763.148210] type=1400 audit(1314014859.480:129): apparmor="ALLOWED" operation="open" parent=29236 profile="/usr/lib/libvirt/virt-aa-helper" name="/var/lib/nova/instances/_base/77de68daecd823babbb58edb1c8e14d7106e83bb" pid=22033 comm="virt-aa-helper" requested_mask="r" denied_mask="r" fsuid=0 ouid=108
Aug 22 14:07:39 beta kernel: [5180763.492113] type=1400 audit(1314014859.830:130): apparmor="STATUS" operation="profile_load" name="libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea" pid=22034 comm="apparmor_parser"
Aug 22 14:07:40 beta kernel: [5180763.925735] device vnet0 entered promiscuous mode
Aug 22 14:07:40 beta kernel: [5180763.927531] br12: port 2(vnet0) entering forwarding state
Aug 22 14:07:40 beta kernel: [5180763.927535] br12: port 2(vnet0) entering forwarding state
Aug 22 14:07:41 beta libvirtd: 14:07:41.355: 29236: error : qemuMonitorCommandWithHandler:255 : cannot send monitor command 'info chardev': Connection reset by peer
Aug 22 14:07:41 beta libvirtd: 14:07:41.355: 29236: error : qemuMonitorTextGetPtyPaths:2001 : operation failed: failed to retrieve chardev info in qemu with 'info chardev'
Aug 22 14:07:41 beta kernel: [5180765.364547] br12: port 2(vnet0) entering forwarding state
Aug 22 14:07:41 beta multipathd: no /block/ in '/devices/virtual/net/vnet0/queues/rx-0'
Aug 22 14:07:41 beta kernel: [5180765.440309] device vnet0 left promiscuous mode
Aug 22 14:07:41 beta kernel: [5180765.440314] br12: port 2(vnet0) entering disabled state
Aug 22 14:07:42 beta kernel: [5180765.702946] type=1400 audit(1314014862.040:131): apparmor="STATUS" operation="profile_remove" name="libvirt-16b2997e-9ffd-7514-4762-ac8909a349ea" pid=22242 comm="apparmor_parser"

Found the real problem.
The vm was a natty UEC image. Even if I was deleting and recreating the vm, the kernel and ramdisk files were always taken from a zero bytes files previously created by a failed deploy.
They were cached on /var/lib/nova/instances/_base.
I deleted the content of the directory and reverted to an enforcing apparmor configuration: everything is working fine.

Sohail Aslam (sohail-aslam) said : #3

Thanks for posting this update. In my case, the instances were not launching on a second nova-compute node. I deleted the /var/lib/nova/instance/_base directory on the slave node and the now the instances do launch properly. I have two nodes with "--scheduler_driver=nova.scheduler.simple.SimpleScheduler" in the /etc/nova/nova.conf.