Migrating 'in-use' volume failed with Error "Object is already attached to session"

[Tina Tang]

When migrate an in used volume with option '--force-host-copy True', sometimes, below Exception was thrown:

1496739 2015-03-18 11:30:44.267 602 ERROR oslo_messaging.rpc.dispatcher [-] Exception during message handling: Object '<Volume at 0x7fe163f6ee10>' is already attached to session '490' (this is '492')
1496740 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher Traceback (most recent call last):
1496741 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", lin e 142, in _dispatch_and_reply
1496742 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher executor_callback))
1496743 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", lin e 186, in _dispatch
1496744 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher executor_callback)
1496745 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", lin e 130, in _do_dispatch
1496746 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher result = func(ctxt, **new_args)
1496747 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
1496748 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
1496749 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
1496750 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
1496751 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
1496752 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
1496753 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
1496754 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
1496755 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
1496756 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
1496757 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
1496758 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
1496759 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/cinder/cinder/volume/manager.py", line 1395, in migrate_volume
1496760 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher self.db.volume_update(ctxt, volume_ref['id'], updates)
1496761 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 85, in _ _exit__
1496762 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher six.reraise(self.type_, self.value, self.tb)
1496763 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/cinder/cinder/volume/manager.py", line 1380, in migrate_volume
1496764 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher new_type_id)
1496765 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/cinder/cinder/volume/manager.py", line 1175, in _migrate_volume_ge neric
1496766 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher new_volume = self.db.volume_create(ctxt, new_vol_values)
1496767 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/cinder/cinder/db/api.py", line 169, in volume_create
1496768 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher return IMPL.volume_create(context, values)
1496769 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 181, in wrapper
1496770 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher return f(*args, **kwargs)
1496771 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/cinder/cinder/db/sqlalchemy/api.py", line 1048, in volume_create
1496772 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher session.add(volume_ref)
1496773 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1558, in add
1496774 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher self._save_or_update_state(state)
1496775 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1570, in _save_or_update_state
1496776 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher self._save_or_update_impl(state)
1496777 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1825, in _save_or_update_impl
1496778 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher self._save_impl(state)
1496779 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1797, in _save_impl
1496780 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher self._attach(state)
1496781 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1915, in _attach
1496782 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher state.session_id, self.hash_key))
1496783 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher InvalidRequestError: Object '<Volume at 0x7fe163f6ee10>' is already attached to sessi on '490' (this is '492')
1496784 2015-03-18 11:30:44.267 602 TRACE oslo_messaging.rpc.dispatcher

=======================================
This was seen in all-in one node which set up by devstack
cinder-manage version list: 2015.1

[Jay Bryant (jsbryant)]

Adding Vincent.

[Jay Bryant (jsbryant)]

mtanino has confirmed this. Vincent, if you have a chance can you take a look please?

Thanks!

[Mitsuhiro Tanino (mitsuhiro-tanino)]

I could reproduce this error case using both tgt SCSI target and LIO scsi target.

I think with or without '--force-host-copy True' parameter does not matter to reproduce this.
Also this bug occurs only if the volume is attached to guest VM. Without volume attachment, we can successfully migrate the volume to other back-end.

During reproduction of this bug, I tried to migrate volume several times and I met an another error case.
The error log is following. This error case looks like also related to Database

http://paste.openstack.org/show/193612/

[Tina Tang (tina-tang)]

We also saw the error mentioned in the last comment from Mitsuhiro in http://paste.openstack.org/show/193612/

Another bug has been reported several days ago, maybe they are related.

https://bugs.launchpad.net/cinder/+bug/1433019

[Vincent Hou (houshengbo)]

Thank you for reporting issues about migration. I will take a look and come back.

[Vincent Hou (houshengbo)]

I have the same question about which kind of back-end you are using?
Is it general issue to LVM? Or some other specific back-ends?

[Tina Tang (tina-tang)]

Hi Vincent,

I am seen this issue with EMC VNX driver in a multiple backend enviornment. However, seems mtanino has seen it with 'tgt SCSI target', is it LVM?

Thanks,
Tina

[Vincent Hou (houshengbo)]

All right, this error happened to LVM for sure, e.g. between two type of LVMs. I got the same error.

[Vincent Hou (houshengbo)]

This bug is duplicate of Bug 1433019, since they are both about of failing to migrate the volume from one type to another type via retype.

This exception in Bug 1433019 is raised for the first time when we try the retype command. After it fails, if we try the retype command again, the exception raised in this bug will be thrown. The errors show up alternatively. In my opinion, the key is to resolve the first exception. Then see if the second disappears as well.