Volume says it is attached, but doesn't show up in guest

Possibly relevant log extract from the compute host:

2011-07-22 17:34:35,396 DEBUG nova.rpc [-] received {u'_context_request_id': u'MFXGNIG4RLVB99USLQ2-', u'_context_read_deleted': False, u'args': {u'instance_id': 22, u'mountpoint': u'/dev/vd
z', u'volume_id': 5}, u'_context_is_admin': True, u'_context_timestamp': u'2011-07-22T17:34:39Z', u'_context_user': u'admin', u'method': u'attach_volume', u'_context_project': u'default-pro
ject', u'_context_remote_address': u'10.4.0.24'} from (pid=27378) _receive /usr/lib/pymodules/python2.6/nova/rpc.py:167
2011-07-22 17:34:35,397 DEBUG nova.rpc [-] unpacked context: {'timestamp': u'2011-07-22T17:34:39Z', 'remote_address': u'10.4.0.24', 'project': u'default-project', 'is_admin': True, 'user':
u'admin', 'request_id': u'MFXGNIG4RLVB99USLQ2-', 'read_deleted': False} from (pid=27378) _unpack_context /usr/lib/pymodules/python2.6/nova/rpc.py:331
2011-07-22 17:34:35,397 INFO nova.compute.manager [MFXGNIG4RLVB99USLQ2- admin default-project] check_instance_lock: decorating: |<function attach_volume at 0x2fbcde8>|
2011-07-22 17:34:35,398 INFO nova.compute.manager [MFXGNIG4RLVB99USLQ2- admin default-project] check_instance_lock: arguments: |<nova.compute.manager.ComputeManager object at 0x2eba510>| |<
nova.context.RequestContext object at 0x43ca950>| |22|
2011-07-22 17:34:35,398 DEBUG nova.compute.manager [MFXGNIG4RLVB99USLQ2- admin default-project] instance 22: getting locked state from (pid=27378) get_lock /usr/lib/pymodules/python2.6/nova
/compute/manager.py:701
2011-07-22 17:34:35,455 INFO nova.compute.manager [MFXGNIG4RLVB99USLQ2- admin default-project] check_instance_lock: locked: |False|
2011-07-22 17:34:35,455 INFO nova.compute.manager [MFXGNIG4RLVB99USLQ2- admin default-project] check_instance_lock: admin: |True|
2011-07-22 17:34:35,455 INFO nova.compute.manager [MFXGNIG4RLVB99USLQ2- admin default-project] check_instance_lock: executing: |<function attach_volume at 0x2fbcde8>|
2011-07-22 17:34:35,498 AUDIT nova.compute.manager [MFXGNIG4RLVB99USLQ2- admin default-project] instance 22: attaching volume 5 to /dev/vdz
2011-07-22 17:34:35,509 WARNING nova.volume.driver [-] ISCSI provider_location not stored, using discovery
2011-07-22 17:34:35,510 DEBUG nova.utils [-] Running cmd (subprocess): sudo iscsiadm -m discovery -t sendtargets -p cc-vm-3 from (pid=27378) execute /usr/lib/pymodules/python2.6/nova/utils.py:150
2011-07-22 17:34:35,544 DEBUG nova.volume.driver [-] ISCSI Discovery: Found 10.4.0.24:3260,1 iqn.2010-10.org.openstack:volume-00000005 from (pid=27378) _get_iscsi_properties /usr/lib/pymodules/python2.6/nova/volume/driver.py:409
2011-07-22 17:34:35,544 DEBUG nova.utils [-] Running cmd (subprocess): sudo iscsiadm -m node -T iqn.2010-10.org.openstack:volume-00000005 -p 10.4.0.24:3260 --login from (pid=27378) execute /usr/lib/pymodules/python2.6/nova/utils.py:150
2011-07-22 17:34:36,068 DEBUG nova.volume.driver [-] iscsiadm --login: stdout=Logging in to [iface: default, target: iqn.2010-10.org.openstack:volume-00000005, portal: 10.4.0.24,3260]
Login to [iface: default, target: iqn.2010-10.org.openstack:volume-00000005, portal: 10.4.0.24,3260]: successful
 stderr= from (pid=27378) _run_iscsiadm /usr/lib/pymodules/python2.6/nova/volume/driver.py:436
2011-07-22 17:34:36,069 DEBUG nova.utils [-] Running cmd (subprocess): sudo iscsiadm -m node -T iqn.2010-10.org.openstack:volume-00000005 -p 10.4.0.24:3260 ('--op', 'update', '-n', 'node.startup', '-v', 'automatic') from (pid=27378) execute /usr/lib/pymodules/python2.6/nova/utils.py:150
2011-07-22 17:34:36,080 DEBUG nova.volume.driver [-] iscsiadm ('--op', 'update', '-n', 'node.startup', '-v', 'automatic'):
BEGIN RECORD 2.0-871
node.name = iqn.2010-10.org.openstack:volume-00000005
node.tpgt = 1
node.startup = manual
iface.hwaddress = <empty>
iface.ipaddress = <empty>
iface.iscsi_ifacename = default
iface.net_ifacename = <empty>
iface.transport_name = tcp
iface.initiatorname = <empty>
node.discovery_address = cc-vm-3
node.discovery_port = 3260
node.discovery_type = send_targets
node.session.initial_cmdsn = 0
node.session.initial_login_retry_max = 8
node.session.xmit_thread_priority = -20
node.session.cmds_max = 128
node.session.queue_depth = 32
node.session.auth.authmethod = None
node.session.auth.username = <empty>
node.session.auth.password = <empty>
node.session.auth.username_in = <empty>
node.session.auth.password_in = <empty>
node.session.timeo.replacement_timeout = 120
node.session.err_timeo.abort_timeout = 15
node.session.err_timeo.lu_reset_timeout = 20
node.session.err_timeo.host_reset_timeout = 60
node.session.iscsi.FastAbort = Yes
node.session.iscsi.InitialR2T = No
node.session.iscsi.ImmediateData = Yes
node.session.iscsi.FirstBurstLength = 262144
node.session.iscsi.MaxBurstLength = 16776192
node.session.iscsi.DefaultTime2Retain = 0
node.session.iscsi.DefaultTime2Wait = 2
node.session.iscsi.MaxConnections = 1
node.session.iscsi.MaxOutstandingR2T = 1
node.session.iscsi.ERL = 0
node.conn[0].address = 10.4.0.24
node.conn[0].port = 3260
node.conn[0].startup = manual
node.conn[0].tcp.window_size = 524288
node.conn[0].tcp.type_of_service = 0
node.conn[0].timeo.logout_timeout = 15
node.conn[0].timeo.login_timeout = 15
node.conn[0].timeo.auth_timeout = 45
node.conn[0].timeo.noop_out_interval = 5
node.conn[0].timeo.noop_out_timeout = 5
node.conn[0].iscsi.MaxRecvDataSegmentLength = 262144
node.conn[0].iscsi.HeaderDigest = None
node.conn[0].iscsi.DataDigest = None
node.conn[0].iscsi.IFMarker = No
node.conn[0].iscsi.OFMarker = No
# END RECORD
 stderr= from (pid=27378) _run_iscsiadm /usr/lib/pymodules/python2.6/nova/volume/driver.py:436
2011-07-22 17:34:36,094 WARNING nova.volume.driver [-] ISCSI volume not yet found at: /dev/disk/by-path/ip-10.4.0.24:3260-iscsi-iqn.2010-10.org.openstack:volume-00000005-lun-0. Will rescan
& retry. Try number: 0
2011-07-22 17:34:36,094 DEBUG nova.utils [-] Running cmd (subprocess): sudo iscsiadm -m node -T iqn.2010-10.org.openstack:volume-00000005 -p 10.4.0.24:3260 --rescan from (pid=27378) execute
 /usr/lib/pymodules/python2.6/nova/utils.py:150
2011-07-22 17:34:36,110 DEBUG nova.volume.driver [-] iscsiadm --rescan: stdout=Rescanning session [sid: 3, target: iqn.2010-10.org.openstack:volume-00000005, portal: 10.4.0.24,3260]
 stderr= from (pid=27378) _run_iscsiadm /usr/lib/pymodules/python2.6/nova/volume/driver.py:436
2011-07-22 17:34:37,111 DEBUG nova.volume.driver [-] Found iSCSI node /dev/disk/by-path/ip-10.4.0.24:3260-iscsi-iqn.2010-10.org.openstack:volume-00000005-lun-0 (after 1 rescans) from (pid=2
7378) discover_volume /usr/lib/pymodules/python2.6/nova/volume/driver.py:492
2011-07-22 17:41:19,832 DEBUG nova.rpc [-] received {u'_msg_id': u'66d56ec141c946aa9d58bcfa85dfab58', u'_context_read_deleted': False, u'_context_request_id': u'342LKIVBSW80AA5DMPPL', u'arg
s': {u'instance_id': 22}, u'_context_is_admin': True, u'_context_timestamp': u'2011-07-22T17:41:23Z', u'_context_user': u'admin', u'method': u'get_console_output', u'_context_project': u'default-project', u'_context_remote_address': u'10.4.0.24'} from (pid=27378) _receive /usr/lib/pymodules/python2.6/nova/rpc.py:167
2011-07-22 17:41:19,833 DEBUG nova.rpc [-] unpacked context: {'timestamp': u'2011-07-22T17:41:23Z', 'remote_address': u'10.4.0.24', 'project': u'default-project', 'is_admin': True, 'user': u'admin', 'request_id': u'342LKIVBSW80AA5DMPPL', 'read_deleted': False} from (pid=27378) _unpack_context /usr/lib/pymodules/python2.6/nova/rpc.py:331

root@cnode-1-3-4:/var/log/nova# iscsiadm -m node
10.4.0.24:3260,1 iqn.2010-10.org.openstack:volume-00000005
10.4.0.24:3260,1 iqn.2010-10.org.openstack:volume-00000004
so they are visible to the compute host it seems, so I'm guessing there's something about getting those mapped up and into the guest that isn't working & that I don't yet understand.

(p.s. I experimented with 2 volumes. Neither showed up. The first one I could detach. The second one throws errors when detaching, and never shows up as detached. Furthermore, it appears to prevent the instance from being correctly terminated, so the instance won't fully go away. The error is File "/usr/lib/pymodules/python2.6/nova/virt/libvirt_conn.py", line 454, in detach_volume / 'NotFound: No disk at vdz'. I don't know why I didn't get that when I tried attaching the first volume, because I did try that one at /dev/vdc and /dev/vdx and it never showed up, but did let me detach it.)

(p.p.s. this is with kvm if that matters.)

Fyi, the volume will not be at /dev/vdz. That is the attach point from the hypervisors view, but the guest will pick its own name. it will show up in the next available slot (usually /dev/vdc)

On Jul 22, 2011, at 2:26 PM, Jon Slenk wrote:

> Question #165695 on OpenStack Compute (nova) changed:
> https://answers.launchpad.net/nova/+question/165695
>
> Jon Slenk gave more information on the question:
> (p.p.s. this is with kvm if that matters.)
>
> --
> You received this question notification because you are a member of Nova
> Core, which is an answer contact for OpenStack Compute (nova).

Huh. I'm pretty surprised and confused! Sorry if I've totally misunderstood things.

The man page for euca-attach-volume says "-d local device name (inside the guest VM) to use." guest, not host. The docs http://docs.openstack.org/bexar/openstack-compute/admin/content/ch05s07.html make it look to me like it should be the same device name in the guest. If it is truly true that the guest sees some effectively-kinda-random-from-the-perspective-of-the-admin device name, it would be great to call that out in the docs. :-} (To reiterate, we're on Cactus, in case something about that behaviour has changed since then.)

So I just retried, and the controller could send out the attach, and things showed up in the host logs, but the host does not show any new /dev/vdq i called it this time. There are no /dev/vd* anythings. Looking at syslog, I think if anything it showed up as /dev/sdd or maybe /dev/sdf on the host. BTW, the vg wasn't ever formatted & given a fs, if that is something that can confuse iscsi/nova-volume?

At any rate, all in all now I'm even more befuddled about the expected names of things.

(Looking at the Cactus code, it appears to me (but obviously I don't know what I'm doing) that compute/api.py.attach_volume() is sending the device name as supplied by the euca-attach-volume command in the RPC cast, and looking at virt/libvirt_conn.py.attach_volume() it is just getting the same value "/dev/vdq" for example per what I see in the host's nova-compute.log. But I've never seen it show up on either the host or guest as that yet.)

Sorry for the confusion.

Unfortunately this is a KVM limitation. You can specify a device name to the KVM hypervisor, but the actual means of attach to the guest is over a virtual pci bus. When the guest sees a new device on the pci bus, it picks the next available name (which in most cases is /dev/vdc) and the disk will show up there. If you then detach this disk and attach another one it will show up as /dev/vdd, etc.. The device name is required on the hypervisor side so it can be detached later, but the device name that the hypervisor reports is completely different from the device name in the guest.

Remember that euca is designed to work with AWS which is using xen. Xen will more reliably attach a device to a specific name, so in that case the names are consistent. I've considered a possible workaround in the guest of a udev rule that could query metadata to find the requested attach point and make a symlink to the guest device, but this has not been created yet.

Perhaps this issue needs to be clarified in the docs.

Vish

On Jul 22, 2011, at 3:15 PM, Jon Slenk wrote:

> Question #165695 on OpenStack Compute (nova) changed:
> https://answers.launchpad.net/nova/+question/165695
>
> Status: Answered => Open
>
> Jon Slenk is still having a problem:
> Huh. I'm pretty surprised and confused! Sorry if I've totally
> misunderstood things.
>
> The man page for euca-attach-volume says "-d local device name (inside
> the guest VM) to use." guest, not host. The docs
> http://docs.openstack.org/bexar/openstack-
> compute/admin/content/ch05s07.html make it look to me like it should be
> the same device name in the guest. If it is truly true that the guest
> sees some effectively-kinda-random-from-the-perspective-of-the-admin
> device name, it would be great to call that out in the docs. :-} (To
> reiterate, we're on Cactus, in case something about that behaviour has
> changed since then.)
>
> So I just retried, and the controller could send out the attach, and
> things showed up in the host logs, but the host does not show any new
> /dev/vdq i called it this time. There are no /dev/vd* anythings. Looking
> at syslog, I think if anything it showed up as /dev/sdd or maybe
> /dev/sdf on the host. BTW, the vg wasn't ever formatted & given a fs, if
> that is something that can confuse iscsi/nova-volume?
>
> At any rate, all in all now I'm even more befuddled about the expected
> names of things.
>
> (Looking at the Cactus code, it appears to me (but obviously I don't
> know what I'm doing) that compute/api.py.attach_volume() is sending the
> device name as supplied by the euca-attach-volume command in the RPC
> cast, and looking at virt/libvirt_conn.py.attach_volume() it is just
> getting the same value "/dev/vdq" for example per what I see in the
> host's nova-compute.log. But I've never seen it show up on either the
> host or guest as that yet.)
>
> --
> You received this question notification because you are a member of Nova
> Core, which is an answer contact for OpenStack Compute (nova).